Bug 54986

Summary: httpd hanging on large form submit in ap_run_handler
Product: Apache httpd-2 Reporter: Rich <rtomasso>
Component: AllAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED LATER    
Severity: major Keywords: MassUpdate
Priority: P2    
Version: 2.2.22   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description Rich 2013-05-16 18:34:28 UTC
Have an issue with a customer system. The apache process is completely hanging when trying to process a submitted form. It's a POST with a long list of mac addresses, about 22K of total data. At some point this just stopped working. Smaller submits, up to 20K work, the exact tripping point varies each time we run it.

Running gdb and attaching to the httpd process (recompiled with -g3 flag) I see this, with a breakpoint set at ap_run_handler.

(gdb) bt
#0 ap_run_handler (r=0xdd3bd50) at config.c:157
#1 0x0807990f in ap_invoke_handler (r=0xdd3bd50) at config.c:376
#2 0x08094d45 in ap_process_request (r=0xdd3bd50) at http_request.c:282
#3 0x0dd3bd50 in ?? ()
#4 0x0d632440 in ?? ()
#5 0x00000000 in ?? ()
(gdb) s

And it just hangs. I can't see what r is pointing to.

I find no function definition in the apache source tree for ap_run_handler(). 

Line 157 in config.c is
AP_IMPLEMENT_HOOK_RUN_FIRST(int, handler, (request_rec *r), (r), DECLINED)

Following the code for definitions of this macro, leads me to a rather obfuscated define in apr_hooks.h, line 358
/** macro to implement the hook */
#define APR_IMPLEMENT_EXTERNAL_HOOK_BASE(ns,link,name) \
link##_DECLARE(void) ns##_hook_##name(ns##_HOOK_##name##_t *pf,const char * const *aszPre, \
                                      const char * const *aszSucc,int nOrder) \
    { \

The apache docs are no help, simply notes it as an internal macro.


# uname -a
Linux lab01.net 2.6.18-238.9.1.el5 #1 SMP Tue Apr 12 18:10:13 EDT 2011 x86_64 x86_64 x86_64 GNU/Linux
(I think this is CentOS 5.7) 

# httpd -V
Server version: Apache/2.2.22 (Unix)
Server built:   May 13 2013 11:55:26
Server's Module Magic Number: 20051115:30
Server loaded:  APR 1.4.5, APR-Util 1.3.12
Compiled using: APR 1.4.5, APR-Util 1.4.1
Architecture:   32-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/prefork"
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=128
 -D HTTPD_ROOT="/space/vendor-build/apache"
 -D SUEXEC_BIN="/space/vendor-build/apache/bin/suexec"
 -D DEFAULT_PIDLOG="logs/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_LOCKFILE="logs/accept.lock"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="conf/mime.types"
 -D SERVER_CONFIG_FILE="conf/httpd.conf"

# httpd -l
Compiled in modules:
  core.c
  mod_ssl.c
  prefork.c
  http_core.c
  mod_so.c
Comment 1 Eric Covener 2013-05-16 18:40:27 UTC
What handler/module is expected to process this request?  Usually the  body isn't read until the handler has control. Can you try again with -O0 and don't set a breakpoint, just get a backtrace of the hung thread.
Comment 2 Rich 2013-05-20 18:26:09 UTC
We're running in a mod_perl environment. If I let the process hang I can't get a backtrace.
Comment 3 Rich 2013-05-21 17:52:42 UTC
Rebuilt with the -O0 option I was able to get some more information. In this environment the doc root is "/opt/product/apache/htdocs".

(gdb) bt
#0  ap_run_handler (r=0xce37d20) at config.c:157
#1  0x0807fb5c in ap_invoke_handler (r=0xce37d20) at config.c:376
#2  0x080a33b2 in ap_process_request (r=0xce37d20) at http_request.c:282
#3  0x080a06e0 in ap_process_http_connection (c=0xcb53d08) at http_core.c:190
#4  0x08086b8f in ap_run_process_connection (c=0xcb53d08) at connection.c:43
#5  0x08086fe5 in ap_process_connection (c=0xcb53d08, csd=0xcb53b70) at connection.c:190
#6  0x080a9490 in child_main (child_num_arg=0) at prefork.c:667
#7  0x080a963c in make_child (s=0x8dd2ca8, slot=0) at prefork.c:768
#8  0x080a96af in startup_children (number_to_start=1) at prefork.c:786
#9  0x080a9ae0 in ap_mpm_run (_pconf=0x8dce0a8, plog=0x8e04180, s=0x8dd2ca8) at prefork.c:1007
#10 0x08069dd1 in main (argc=3, argv=0xffa79174) at main.c:753
(gdb) p r
$1 = (request_rec *) 0xce37d20
(gdb) p *r
$2 = {pool = 0xce37ce0, connection = 0xcb53d08, server = 0x8dd2ca8, next = 0x0, prev = 0x0, main = 0x0,
  the_request = 0xce38c60 "POST /sla/create/index.html HTTP/1.1", assbackwards = 0, proxyreq = 0, header_only = 0,
  protocol = 0xce38d00 "HTTP/1.1", proto_num = 1001, hostname = 0xce39220 "209.211.205.181",
  request_time = 1369158013800915, status_line = 0x0, status = 200, method = 0xce38cb0 "POST", method_number = 2,
  allowed = 0, allowed_xmethods = 0x0, allowed_methods = 0xce37ec0, sent_bodyct = 0, bytes_sent = 0, mtime = 0,
  chunked = 0, range = 0x0, clength = 0, remaining = 0, read_length = 0, read_body = 0, read_chunked = 0,
  expecting_100 = 0, headers_in = 0xce37ef0, headers_out = 0xce38380, err_headers_out = 0xce38528,
  subprocess_env = 0xce38138, notes = 0xce38680, content_type = 0x8e90c48 "text/html",
  handler = 0x8ded1c8 "perl-script", content_encoding = 0x0, content_languages = 0x0, vlist_validator = 0x0,
  user = 0x0, ap_auth_type = 0x0, no_cache = 0, no_local_copy = 0,
  unparsed_uri = 0xce38cd0 "/sla/create/index.html", uri = 0xce38ce8 "/sla/create/index.html",
  filename = 0xce39348 "/opt/product/apache/htdocs/sla/create/index.html",
  canonical_filename = 0xce39348 "/opt/product/apache/htdocs/sla/create/index.html", path_info = 0xce392c1 "",
  args = 0x0, finfo = {pool = 0xce37ce0, valid = 7598960, protection = 1604, filetype = APR_REG, user = 504,
    group = 110, inode = 6657732, device = 64769, nlink = 1, size = 2608, csize = 4096, atime = 1369157418000000,
    mtime = 1360861380000000, ctime = 1360861380000000,
    fname = 0xce39290 "/opt/product/apache/htdocs/sla/create/index.html", name = 0x0, filehand = 0x0}, parsed_uri = {
    scheme = 0x0, hostinfo = 0x0, user = 0x0, password = 0x0, hostname = 0x0, port_str = 0xce39239 "8080",
    path = 0xce38ce8 "/sla/create/index.html", query = 0x0, fragment = 0x0, hostent = 0x0, port = 8080,
    is_initialized = 1, dns_looked_up = 0, dns_resolved = 0}, used_path_info = 2, per_dir_config = 0xce39590,
  request_config = 0xce387d8, htaccess = 0x0, output_filters = 0xccf1818, input_filters = 0xce39240,
  proto_output_filters = 0xce38be0, proto_input_filters = 0xce39240, eos_sent = 0}


Stepping from here, the process hangs. Running pstack from another window returns nothing.
Comment 4 Mike Rumph 2013-05-22 00:34:46 UTC
(In reply to comment #0)
> I find no function definition in the apache source tree for
> ap_run_handler(). 
> 
> Line 157 in config.c is
> AP_IMPLEMENT_HOOK_RUN_FIRST(int, handler, (request_rec *r), (r), DECLINED)
> 
> Following the code for definitions of this macro, leads me to a rather
> obfuscated define in apr_hooks.h, line 358
> /** macro to implement the hook */
> #define APR_IMPLEMENT_EXTERNAL_HOOK_BASE(ns,link,name) \
> link##_DECLARE(void) ns##_hook_##name(ns##_HOOK_##name##_t *pf,const char *
> const *aszPre, \
>                                       const char * const *aszSucc,int
> nOrder) \
>     { \
> 
> The apache docs are no help, simply notes it as an internal macro.
> 
The function to look for is ap_hook_handler.
This is found in several modules.
One example is server/core.c:
   ap_hook_handler(default_handler,NULL,NULL,APR_HOOK_REALLY_LAST);
This will cause the default_handler function in core.c to be called whenever ap_run_handler is called.
The following documentation may help explain this:
- http://httpd.apache.org/docs/2.2/developer/hooks.html

Perhaps mod_perl should have something like this as well.
Comment 5 Rich 2013-05-22 18:21:51 UTC
I set breakpoints at ap_hook_handler and default_handler, neither of them were reached.

I ran the same form with a small data set so it completed. At the breakpoint for ap_run_handler, I did step and it came back quickly with the next line further down, a call to ap_invoke_handler [config.c:378]. And the form has returned. No meaningful difference in contents of the request object.
Comment 6 William A. Rowe Jr. 2018-11-07 21:09:17 UTC
Please help us to refine our list of open and current defects; this is a mass update of old and inactive Bugzilla reports which reflect user error, already resolved defects, and still-existing defects in httpd.

As repeatedly announced, the Apache HTTP Server Project has discontinued all development and patch review of the 2.2.x series of releases. The final release 2.2.34 was published in July 2017, and no further evaluation of bug reports or security risks will be considered or published for 2.2.x releases. All reports older than 2.4.x have been updated to status RESOLVED/LATER; no further action is expected unless the report still applies to a current version of httpd.

If your report represented a question or confusion about how to use an httpd feature, an unexpected server behavior, problems building or installing httpd, or working with an external component (a third party module, browser etc.) we ask you to start by bringing your question to the User Support and Discussion mailing list, see [https://httpd.apache.org/lists.html#http-users] for details. Include a link to this Bugzilla report for completeness with your question.

If your report was clearly a defect in httpd or a feature request, we ask that you retest using a modern httpd release (2.4.33 or later) released in the past year. If it can be reproduced, please reopen this bug and change the Version field above to the httpd version you have reconfirmed with.

Your help in identifying defects or enhancements still applicable to the current httpd server software release is greatly appreciated.