Apache error log: can it give reasons?

Logging the setenv/rewrite rejection reason

[dstiles]

It would be useful, especially during development, to log the reason why a client was refused access in greater detail. "Denied by config setup" helps a bit but it would help if it gave the rule that it was rejected on.

Reading the apache manual pages it looks as if this is not possible. Or is it?

[not2easy]

Yes. No. Maybe. Somewhat. The first digit of your error code can tell you the type of error. Sometimes that can help you see where to look - but it may not be enough of a hint to be certain of "why?" - and I do not know whether or where you would find that next step.

I have an oulde list that unfortunately is from before the days when I would document my sources. It shows that server response codes of "1xx" show that a request has been received and is being processed. I have never seen one of these so I am guessing it occurs so far upstream of my logs that it is information deemed unhelpful and discarded.

2xx responses are success reports of various types.
3xx tells us that there is some redirection involved.
4xx is an incomplete request (as the familiar 404 tells us "not found").
5xx is the hard one and probably the one that would be most helpful during development. These are errors which have occurred in the server itself. My list shows only the first 5 response codes and I've never seen any of them in logs, but in case they help:

500 Internal Server Error - nasty response that is usually caused by a problem in your Perl code when a CGI program is run.
501 The request cannot be carried out by the server.
502 Bad Gateway - the server you're trying to reach is sending back errors.
503 Temporarily Unavailable - the service or file that is being requested is not currently available.
504 The gateway has timed out. Like the 408 timeout error, but this one occurs at the gateway of the server.
505 The HTTP protocol you are asking for is not supported.

If it helps, I am certain that there are others around here with much more useful information. ;)

[lucy24]

The RewriteLog is your friend. You are right: ordinary error logs are spectacularly unhelpful because all it ever, ever says, regardless of LogLevel, is “request denied by server configuration” (qfm, I forget the exact wording). But since it is your own server, you also have the option of a RewriteLog, with 8 possible levels of detail.

:: quick double-check of docs [httpd.apache.org] ::

You’re on 2.4, right? Then you have even more options.

Example
LogLevel alert rewrite:trace3
...
Those familiar with earlier versions of mod_rewrite will no doubt be looking for the RewriteLog and RewriteLogLevel directives. This functionality has been completely replaced by the new per-module logging configuration mentioned above.

To get just the mod_rewrite-specific log messages, pipe the log file through grep:
tail -f error_log|fgrep '[rewrite:'

It was you, wasn't it, that posted elsewhere about selective host lookups? Here's one more postprocessing routine you could run, if so.

All this would seem to imply that you can similarly log mod_setenvif, or any other module [httpd.apache.org] (forums will probably eat the #loglevel anchor, but you can find it) that suits your fancy.

LogLevel [module:]level [module:level] ... 

Time to experiment :)

Post back and tell us what you find, as I'm still on 2.2. (It occurred to me recently that I can undoubtedly get a 2.4 version of MAMP, but I'm hesitant to do so since the main purpose of my MAMP install is to replicate what I see on my live site.)

[phranque]

if you are on apache 2.4 you can use the LogLevel directive to control the level of error log reporting at the module level:
https://httpd.apache.org/docs/current/mod/core.html#loglevel

in your case you want to adjust the verbosity of the messages recorded in the error logs for the modules you are using to control access.
(i.e. mod_rewrite since you are using RewriteRule and mod_access if you are also using Allow/Deny directives)

[lucy24]

mod_access if you are also using Allow

? There’s a mod_access_compat, but that’s just to ease the transition from old-style Allow/Deny to new-style Require/Satisfy.

This raises an interesting question, which can probably be best answered by experiment*: if your access controls are based on one module (mod_authz_host) using values set by a different module (mod_setenvif), which of the two is more useful to log in detail? Will your server grind to a screeching halt if you log both to the highest possible detail level?

Incidentally, I shouldn't have mentioned the RewriteLog (or its 2.4 equivalent), since I don't think OP's site uses mod_rewrite for access control, so it's just another source of confusion. Useful in other ways, though, like “why the ### did that get redirected?”


* With said experimentation to be done, sadly, by someone other than me :(

[phranque]

I don't think OP's site uses mod_rewrite for access control

from the OP's provided meta description:

Logging the setenv/rewrite rejection reason

if your access controls are based on one module (mod_authz_host) using values set by a different module (mod_setenvif), which of the two is more useful to log in detail?

wouldn't it be great if apache documentation for each module showed examples of expected log results for the various loglevels?

[dstiles]

not2easy: sorry, I knew that but thanks anyway.

Lucy, phranque: thanks! I should have paid more attention to that when I first saw it but failed to understand the implications.

I added...
LogLevel alert setenv:trace3
...to setenvif.conf (within the "IfModule" although probably not relevant since the module is obviously loaded). Worked fine when I sent it a bingbot ua from my local machine, though each request from the browser added two unexpected lines...

[datetime] [setenvif:trace2] [pid] mod_setenvif.c(622): [client nn.nn.nnn.nn:59992] Setting fake_bing, referer: https://www.example.com/about.php
[datetime] [setenvif:trace2] [pid] mod_setenvif.c(622): [client nn.nn.nnn.nn:59992] Setting evil_robot, referer: https://www.example.com/about.php
[datetime] [setenvif:trace2] [pid] mod_setenvif.c(622): [client nn.nn.nnn.nn:59992] Setting evil_robot, referer: https://www.example.com/about.php
[datetime] [setenvif:trace2] [pid] mod_setenvif.c(622): [client nn.nn.nnn.nn:59992] Setting bad_ua, referer: https://www.example.com/about.php

The second evil_robot line is puzzling since it should only trigger that once

The final log line sets bad_ua. I think this is triggered by the test for an alpha-numeric UA...
BrowserMatch ^[a-zA-Z0-9\s\-\.]+$ bad_ua
...due to me being lazy and setting up a minimal UA in the browser. And this is why I wanted the logging option. :)

Note that I requested trace3 but the log says trace2. Not sure if that is an observation as to which level the error occurred or a deeper error in apache.

Thinking I should add the LogLevel to apache2.conf after the normal LogLevel I moved it and added a rewrite LogLevel as well (separate lines). That failed. Hmm. Adding the line back in setenvif.conf (and leaving the two LogLevels in apache2.conf) worked again. Removed the setenvif.conf one and the rewrite from apache2.conf and all ok. Reversed the order of the apache2.conf lines and it worked again. Haven't yet devised a way to trigger a rewrite one - mainly they are handling things setenv can't do, such as bad referers and querystrings. But it looks as if only one module alert can be set at a time; if more, last one wins. Which means that LogLevel without a module appended is also superceded.

Just got another one that shouldn't happen - dontlog urlwatch works (I think!) but triggers a bad Request_URI. Ah well, I can cope with that sort of thing. :) Useful to know, though.

[lucy24]

The second evil_robot line is puzzling since it should only trigger that once

There's probably some other setenvif directive that you put in for testing and never got around to removing, so two different aspects of the UA string both trigger the setting.

wouldn't it be great if apache documentation for each module

Wasn’t that a Beach Boys song?

But it looks as if only one module alert can be set at a time; if more, last one wins.

Well, phooey. But that's what experimentation is for. Er, this isn't a live site that has to stay in limbo until everything is sorted, is it?

[dstiles]

Lucy:
> some other setenvif directive
No, but it seems it only happens on your fake / evil traps where an env is set and then unset. The trap seems to function correctly, though and reports the same whether or not the trap is real or fake.

These are two live sites which I'm using to get to grips with apache/php on linux after a "life-time" of ASP on Windows - into which I was conned early on (late 1990s) and never managed to escape: I dislike windows!). Both sites are low profile and almost never visited by "real" people, though SEs are enjoying them. One site is about two years old, the other 18. I can afford mistakes with both.

[phranque]

wouldn't it be great if apache documentation for each module

Wasn’t that a Beach Boys song?

Wouldn't It Be Nice?