Bug 56216

Summary: multiple reqtimeout_con_cfg created for each request -> wrong timeout behavior
Product: Apache httpd-2 Reporter: Frank Meier <frank.meier>
Component: mod_reqtimeoutAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED FIXED    
Severity: normal CC: apache_bugzilla
Priority: P2 Keywords: FixedInTrunk
Version: 2.4.7   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Attachments: patch: only create reqtimeout_con_cfg once per connection
mod_reqtimeout.c with more debug logs
apache error_log with debug info during 2 requests on same connection
only create reqtimeout_con_cfg once per connection / reset properly

Description Frank Meier 2014-03-04 16:28:22 UTC
Created attachment 31365 [details]
patch: only create reqtimeout_con_cfg once per connection

while testing mod_reqtimout, I sometimes got strange timeouts i couldn't explain. After adding some debug code to mod_reqtimeout.c I found out that:
1) reqtimeout_init() is called before each request (not only at the start of the connection)
2) therefore for each request a new reqtimeout_con_cfg is created and set as context to the connection config: ap_set_module_config(c->conn_config, &reqtimeout_module, ccfg) and is added to the input filter: ap_add_input_filter("reqtimeout", ccfg, NULL, c);
3) For subsequent Requests I got then calls to reqtimeout_filter(), with each registered reqtimeout_con_cfg. That means during the first Request reqtimeout_filter() was called with the correct reqtime_con_cfg, in the second Request reqtimeout_filter() was called twice() one time with the actual reqtimeout_con_cfg and one time with the one from the first Request. And so forth.
4) Then one call to reqtimeout_filter() with the obsolete ccfg decided to detect a timeout, and the request was aborted

It looks to me, it was thought, reqtimeout_init() reqistered in hook 'ap_hook_process_connection' shall only be called once. But since it is called multiple times, it has to be secured, not to create and register a new reqtimeout_con_cfg each time. See proposed attached patch.
Comment 1 Edward Lu 2014-03-05 13:50:16 UTC
Could you post some backtraces of the execution to verify that reqtimeout_init() is indeed being run multiple times in a single connection? It'd be interesting to see where it's getting called from.
Comment 2 Frank Meier 2014-03-06 10:03:32 UTC
I put some additional debug log into mod_reqtimeout.c (see attachment: mod_reqtimeout.c.debug) and made two requests (with telnet) on the same TCP connection. The resulting log (see attachment: two_requests_on_same_connection_debug.log) shows, that the method  reqtimeout_init() is indeed called for each request (first at 10:57:51.982062, second: 10:58:01.277638). 

Further we can see, that in the first request the method reqtimeout_filter() is called with the context:0x58037d30 which was created in the first reqtimeout_init() call; and in the second request it is again called with the context from the first request and also with the new one 0x58037f50 created in the second reqtimeout_init() call.
Comment 3 Frank Meier 2014-03-06 10:04:51 UTC
Created attachment 31370 [details]
mod_reqtimeout.c with more debug logs
Comment 4 Frank Meier 2014-03-06 10:05:40 UTC
Created attachment 31371 [details]
apache error_log with debug info during 2 requests on same connection
Comment 5 Frank Meier 2014-03-06 10:32:00 UTC
I got you 2 backtraces in reqtimeout_init. 2 Request on the same connection with telnet:

Breakpoint 1, reqtimeout_init (c=0x7ffff0007d00) at mod_reqtimeout.c:338
338         cfg = ap_get_module_config(c->base_server->module_config,
(gdb) bt
#0  reqtimeout_init (c=0x7ffff0007d00) at mod_reqtimeout.c:338
#1  0x00005555555ba380 in ap_run_process_connection (c=0x7ffff0007d00) at connection.c:41
#2  0x00005555555d2845 in process_socket (my_thread_num=1, my_child_num=0, cs=0x7ffff0007c88, sock=0x7ffff0007a80, p=<optimized out>, thd=0x555555842038) at event.c:970
#3  worker_thread (thd=0x555555842038, dummy=<optimized out>) at event.c:1815
#4  0x00007ffff6c96f3a in start_thread () from /lib/libpthread.so.0
#5  0x00007ffff67ccc3d in clone () from /lib/libc.so.6
(gdb) cont
Continuing.
[Switching to Thread 0x7ffff5cd0700 (LWP 15328)]

Breakpoint 1, reqtimeout_init (c=0x7ffff0007d00) at mod_reqtimeout.c:338
338         cfg = ap_get_module_config(c->base_server->module_config,
(gdb) bt
#0  reqtimeout_init (c=0x7ffff0007d00) at mod_reqtimeout.c:338
#1  0x00005555555ba380 in ap_run_process_connection (c=0x7ffff0007d00) at connection.c:41
#2  0x00005555555d2845 in process_socket (my_thread_num=0, my_child_num=0, cs=0x7ffff0007c88, sock=0x7ffff0007a80, p=<optimized out>, thd=0x555555842008) at event.c:970
#3  worker_thread (thd=0x555555842008, dummy=<optimized out>) at event.c:1815
#4  0x00007ffff6c96f3a in start_thread () from /lib/libpthread.so.0
#5  0x00007ffff67ccc3d in clone () from /lib/libc.so.6
(gdb) cont
Continuing.
Comment 6 Frank Meier 2014-03-06 10:40:14 UTC
Created attachment 31372 [details]
only create reqtimeout_con_cfg once per connection / reset properly

added improved patch: initialize reqtimeout_con_cfg with zeros in case of reusage.
Comment 7 Ruediger Pluem 2014-03-06 12:10:56 UTC
I see that you are using the event MPM. Can you still reproduce this using the worker MPM?
Comment 8 Frank Meier 2014-03-06 13:30:15 UTC
Funny thing. I cannot reproduce this behavior with the worker MPM. There reqtimeout_init() is only called once at the beginning of the first request.

So it seems the event MPM does not handle the ap_hook_process_connection() hook the same way as the worker MPM. This could potentially break other modules depending on this hook.
Comment 9 Eric Covener 2014-03-06 17:42:12 UTC
This seems to be a basic difference between event and worker, worker loops over requests in its 1 call to ap_hook_process_connection() whereas event pulls one off and returns afterwards as the MPM drives ap_run_process_connection() over and over.

Very few consumers in-tree of ap_hook_process_connection. Seems a bit odd.
Comment 10 Eric Covener 2014-03-23 19:00:07 UTC
Thanks for the report/patch, committed to trunk with some style changes
Comment 11 Eric Covener 2014-03-23 19:00:31 UTC
Thanks for the report/patch, committed to trunk with some style changes in 1580568. Will propose for 2.4.10.
Comment 12 Christophe JAILLET 2014-08-18 07:51:46 UTC
Fixed and released in 2.4.10