Bug 46969 - CustomLog format %m always GET on errors with local ErrorDocument
Summary: CustomLog format %m always GET on errors with local ErrorDocument
Status: RESOLVED DUPLICATE of bug 62186
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: Core (show other bugs)
Version: 2.2.11
Hardware: Sun Solaris
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-04-05 06:44 UTC by evanc
Modified: 2018-05-31 19:22 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description evanc 2009-04-05 06:44:05 UTC
CustomLog format %m is always GET in an error condition when the error message is provided by a local ErrorDocument.  %m is correct for a successful connection.  %m is also correct with ErrorDocument disabled.

The local ErrorDocument is a .shtml with server-side includes enabled.  REQUEST_METHOD as reported by printenv in the .shtml is also GET.  The original method is stored in REDIRECT_REQUEST_METHOD.  I tried to log
"%<m" instead to get the original request's method, but that also logged
GET instead of the original method.

Running Apache 2.2.11 as forward proxy server, with mod_proxy, mod_proxy_http and mod_proxy_connect.  Problem can be duplicated with HEAD and CONNECT requests to unavailable/invalid URLs.
Comment 1 Nick Kew 2009-08-22 18:47:57 UTC
I am able to reproduce part of this: namely GET is always shown as REQUEST_METHOD in a .shtml errordocument.  However, my access log always shows the original method, as expected.  That's with a 404.shtml errordocument.

Can you post a configuration extract and request that'll demonstrate this?
Comment 2 evanc 2009-09-06 21:32:09 UTC
(In reply to comment #1)
> I am able to reproduce part of this: namely GET is always shown as
> REQUEST_METHOD in a .shtml errordocument.  However, my access log always shows
> the original method, as expected.  That's with a 404.shtml errordocument.
> 
> Can you post a configuration extract and request that'll demonstrate this?

Sorry for the delay.  Here is a short configuration that demonstrates this:

User nobody
Group nobody
LogFormat "%t %m %U%q %>s" access_log
CustomLog "logs/access_log" access_log
ErrorLog "logs/error_log"
LogLevel crit

DefaultType text/plain
AddType text/html .shtml
AddOutputFilter INCLUDES .shtml
ErrorDocument 400 /error/template.shtml
ErrorDocument 403 /error/template.shtml
ErrorDocument 404 /error/template.shtml
ErrorDocument 502 /error/template.shtml
ErrorDocument 503 /error/template.shtml

<Directory />
        AllowOverride None
        Deny from all
</Directory>

DocumentRoot "/usr/local/apache/htdocs"
<Directory "/usr/local/apache/htdocs/error">
        Options IncludesNoExec
        Allow from all
</Directory>

ProxyRequests On
Listen 8080
<Proxy *>
        Deny from all
</Proxy>

Server version: 2.2.13

Request via proxy: https://doesnotexist.mycompany.com/ (CONNECT doesnotexist.mycompany.com:443)
Access log result:
[07/Sep/2009:04:00:01 +0000] GET doesnotexist.mycompany.com:443 403

Request via proxy: HEAD http://doesntoexist.mycompany.com/
Access log result:
[07/Sep/2009:04:13:03 +0000] GET http://doesnotexist.ca.nortel.com/ 403

In either case, GET is logged instead of CONNECT.

Thanks very much for your help.

Evan
Comment 3 Petar Bogdanovic 2017-05-23 14:35:22 UTC
ErrorDocuments are delivered through internal redirects so we end up
with two requests, the original (POST) and the new request (GET).

When resolving REQUEST_METHOD, you should try to resolve the original
REQUEST_METHOD (which would be %<{REQUEST_METHOD}e in mod_log_config
lingo).  Otherwise it will always resolve to "GET" in case of internal
redirects to some ErrorDocument.

It's different with %m, %m will always be "GET" by design:

httpd-2.4.25/modules/http/http_request.c:
188     else if (custom_response[0] == '/') {
189         const char *error_notes;
190         r->no_local_copy = 1;       /* Do NOT send HTTP_NOT_MODIFIED for
191                                      * error documents! */
192         /*
193          * This redirect needs to be a GET no matter what the original
194          * method was.
195          */
196         apr_table_setn(r->subprocess_env, "REQUEST_METHOD", r->method);
197 
198         /*
199          * Provide a special method for modules to communicate
200          * more informative (than the plain canned) messages to us.
201          * Propagate them to ErrorDocuments via the ERROR_NOTES variable:
202          */
203         if ((error_notes = apr_table_get(r->notes,
204                                          "error-notes")) != NULL) {
205             apr_table_setn(r->subprocess_env, "ERROR_NOTES", error_notes);
206         }
207         r->method = "GET";
208         r->method_number = M_GET;
209         ap_internal_redirect(custom_response, r);
210         return;
211     }

Here, apr_die_r saves the original method into REQUEST_METHOD before
resetting method/method_number to "GET"/M_GET and the comment before
apr_table_setn indicates that this is done on purpose.

So if you need the original method, use %<{REQUEST_METHOD}e instead of %m.
Comment 4 Christophe JAILLET 2018-05-31 19:22:29 UTC
Closing because:
  - 2.2.x branch is EOL
  - %m behavior looks correct as per doc
  - a workaround is proposed (untested by me)
  - %<m behavior is a duplicate of bug 62186 which is fixed in httpd 2.4.34

*** This bug has been marked as a duplicate of bug 62186 ***