[SOLVED] Strange Apache CustomLog behavior

Issue

I'm adding a Docker healthcheck function which I've successfully done in one container, but adding the same code to a different container is behaving strangely.

Essentially, I'm simply trying to not log certain requests, using an env var.

In dockerfile:

HEALTHCHECK CMD curl -ILfSs http://localhost:80 -A "HealthCheck" || exit 1

RUN ln -sf /dev/stdout /var/www/logs/access.log \
    && ln -sf /dev/stdout /var/www/logs/transfer.log \
    && ln -sf /dev/stdout /var/www/logs/ssl-transfer.log \
    && ln -sf /dev/stderr /var/www/logs/error.log \
    && ln -sf /dev/stderr /var/www/logs/ssl-error.log

In httpd.conf:

<IfModule log_config_module>
    LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
    LogFormat "%h %l %u %t \"%r\" %>s %b" common

    <IfModule logio_module>
      LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O" combinedio
    </IfModule>

    <IfModule setenvif_module>
       BrowserMatchNoCase ^healthcheck nolog
    </IfModule>

    CustomLog "logs/access.log" combinedio env=!nolog

</IfModule>

So now when the healthcheck ticks, the log which would normally show this:

127.0.0.1 - - [05/Oct/2022:03:22:13 +0000] "HEAD / HTTP/1.1" 200 - "-" "HealthCheck" 74 1095

shows this (it shouldn't be showing anything at all since the env var gets set when the UserAgent matches 'healthcheck'):

127.0.0.1 - - [05/Oct/2022:05:17:46 +0000] "HEAD / HTTP/1.1" 200 -

It acts almost as if it's doing a replace of everything that matches 'healthcheck' and after, with nothing at all (empty string), which I don't think it's even supposed to be capable of doing(?).

I've tested to make sure that the only healthcheck being called is this one in httpd.conf by commenting out the BrowserMatchNoCase ^healthcheck nolog line, and it indeed then just shows the usual, expected line containing the "HealthCheck" useragent.

Solution

Mystery solved; there was a "hidden" TransferLog in the configs duking it out with my CustomLog, so my stuff was actually working as intended, but the TransferLog was also being called, so they were both outputting to the log at the same time for each HealthCheck call.

I say "hidden" because even though it was there in plain sight, it was the first time I've personally encountered the TransferLog directive; I've always just used CustomLog, and wasn't aware how TransferLog worked in combination with CustomLog when they're both present.

Removing TransferLog entirely and only using CustomLog (because it allows log formatting whereas TransferLog doesn't) did the trick.

Answered By - J. Scott Elblein

Answer Checked By - David Goodson (WPSolving Volunteer)