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.
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.
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.
Created attachment 31370 [details] mod_reqtimeout.c with more debug logs
Created attachment 31371 [details] apache error_log with debug info during 2 requests on same connection
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.
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.
I see that you are using the event MPM. Can you still reproduce this using the worker MPM?
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.
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.
Thanks for the report/patch, committed to trunk with some style changes
Thanks for the report/patch, committed to trunk with some style changes in 1580568. Will propose for 2.4.10.
Fixed and released in 2.4.10