Dear Graham, I inherited a service from my predecessor using mod_wsgi. The service itself is functional, but longer running requests (~10 min) don't end up in a response to the client, even though logs don't really hint to any bigger issues. My best guess is some kind of timeout issue, but I am at my wits end which config that should be.
The server runs in a docker container where it starts an apache server with mod_wsgi configured and python using flask to handle the requests. It runs with theses versions: - Apache 2.4.62 - mod_wsgi: 4.7.1 - Python: 3.8 Due to forking of the process using the multiprocessing package I switched to the prefork MPM. In the current long running requests that don't respond this forking doesn't happen, so it shouldn't be an issue here. I had a look here https://groups.google.com/g/modwsgi/c/zuhFREjOE8M and massively increased all timeouts to test if this is the issue, but that doesn't seem to be the case. <VirtualHost *:443> ServerName someservice.de WSGIDaemonProcess python_service processes=10 threads=1 display-name=someservice maximum-requests=200 python-home=/var/www/someservice/venv socket-timeout=1800 connect-timeout=1800 request-timeout=1800 graceful-timeout=1800 eviction-timeout=1800 queue-timeout=1800 WSGIScriptAlias /python_service /var/www/someservice/someservice_service/someservice_service_controller.py process-group=python_service application-group=%{GLOBAL} WSGIApplicationGroup %{GLOBAL} SSLEngine On SSLCertificateFile /opt/pki/certs.crt SSLCertificateKeyFile /opt/pki/certs.key SSLCertificateChainFile /opt/pki/certs.pem <Directory /var/www/someservice/someservice_service> </Directory> <Location /python_service> WSGIProcessGroup python_service </Location> </VirtualHost> I also increased Timeout and SSLSessionCacheTimeout in the apache2.conf in the entrypoint.sh which the docker container calls on startup: sed -i "s/Timeout 300/Timeout 1800/g" /etc/apache2/apache2.conf sed -i "s/SSLSessionCacheTimeout 300/SSLSessionCacheTimeout 1800/g" /etc/apache2/mods-available/ssl.conf apachectl -D FOREGROUND I did a run with maximum trace logs below. I shortened / censored some logs. Date,Message "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804413 2025] [wsgi:error] [pid 28:tid 410] [remote <client-ip>:58971] INFO in someservice_service_controller: Last log here" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804779 2025] [core:trace6] [pid 28:tid 410] core_filters.c(828): [remote <client-ip>:58971] writev_nonblocking: 229/229" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804806 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(168): [client <client-ip>:58971] Content-Type 'application/json' ..." "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804822 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/xml'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804825 2025] [filter:trace2] [pid 30:tid 36] mod_filter.c(185): [client <client-ip>:58971] Content-Type condition for 'deflate' did not match" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804828 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(168): [client <client-ip>:58971] Content-Type 'application/json' ..." "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804830 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/wasm'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804831 2025] [filter:trace2] [pid 30:tid 36] mod_filter.c(185): [client <client-ip>:58971] Content-Type condition for 'deflate' did not match" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804833 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(168): [client <client-ip>:58971] Content-Type 'application/json' ..." "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804835 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/rss+xml'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804837 2025] [filter:trace2] [pid 30:tid 36] mod_filter.c(185): [client <client-ip>:58971] Content-Type condition for 'deflate' did not match" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804839 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(168): [client <client-ip>:58971] Content-Type 'application/json' ..." "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804841 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/x-javascript'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804843 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/javascript'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804844 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'application/ecmascript'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804846 2025] [filter:trace2] [pid 30:tid 36] mod_filter.c(185): [client <client-ip>:58971] Content-Type condition for 'deflate' did not match" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804848 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(168): [client <client-ip>:58971] Content-Type 'application/json' ..." "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804850 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'text/html'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804852 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'text/plain'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804854 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'text/xml'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804855 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'text/css'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804857 2025] [filter:trace4] [pid 30:tid 36] mod_filter.c(180): [client <client-ip>:58971] ... did not match 'text/javascript'" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804859 2025] [filter:trace2] [pid 30:tid 36] mod_filter.c(185): [client <client-ip>:58971] Content-Type condition for 'deflate' did not match" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804870 2025] [http:trace3] [pid 30:tid 36] http_filters.c(1141): [client <client-ip>:58971] Response sent with status 200, headers:" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804877 2025] [http:trace5] [pid 30:tid 36] http_filters.c(1150): [client <client-ip>:58971] Date: Mon, 23 Jun 2025 07:56:07 GMT" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804880 2025] [http:trace5] [pid 30:tid 36] http_filters.c(1153): [client <client-ip>:58971] Server: Apache/2.4.62 (Debian)" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804882 2025] [http:trace4] [pid 30:tid 36] http_filters.c(971): [client <client-ip>:58971] WWW-Authenticate: Negotiate YIGZBgkqhkiG9...<cut short>" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804885 2025] [http:trace4] [pid 30:tid 36] http_filters.c(971): [client <client-ip>:58971] Content-Length: 158" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804887 2025] [http:trace4] [pid 30:tid 36] http_filters.c(971): [client <client-ip>:58971] Content-Type: application/json" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804909 2025] [ssl:trace4] [pid 30:tid 36] ssl_engine_io.c(1856): [client <client-ip>:58971] coalesce: have 0 bytes, adding 379 more (buckets=1)" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804917 2025] [ssl:trace4] [pid 30:tid 36] ssl_engine_io.c(1856): [client <client-ip>:58971] coalesce: have 379 bytes, adding 158 more (buckets=1)" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804922 2025] [ssl:trace4] [pid 30:tid 36] ssl_engine_io.c(1919): [client <client-ip>:58971] coalesce: passing on 537 bytes" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804929 2025] [ssl:trace6] [pid 30:tid 36] ssl_engine_io.c(894): [client <client-ip>:58971] ssl_filter_write: 537 bytes" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804966 2025] [ssl:trace6] [pid 30:tid 36] ssl_engine_io.c(219): [client <client-ip>:58971] bio_filter_out_write: 566 bytes" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804974 2025] [ssl:trace4] [pid 30:tid 36] ssl_engine_io.c(2428): [client <client-ip>:58971] OpenSSL: write 566/566 bytes to BIO#7fdee0002c50 [mem: 7fdee000e633] (BIO dump follows)" "2025-06-23T08:05:01.804Z","[Mon Jun 23 08:05:01.804978 2025] [ssl:trace7] [pid 30:tid 36] ssl_engine_io.c(2325): [client <client-ip>:58971] +-------------------------------------------------------------------------+" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805082 2025] [ssl:trace7] [pid 30:tid 36] ssl_engine_io.c(2362): [client <client-ip>:58971] | <some SSL key here> "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805084 2025] [ssl:trace7] [pid 30:tid 36] ssl_engine_io.c(2367): [client <client-ip>:58971] +-------------------------------------------------------------------------+" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805086 2025] [ssl:trace6] [pid 30:tid 36] ssl_engine_io.c(894): [client <client-ip>:58971] ssl_filter_write: 0 bytes" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805147 2025] [core:trace6] [pid 30:tid 36] core_filters.c(828): [client <client-ip>:58971] writev_nonblocking: 566/566" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805221 2025] [ssl:trace4] [pid 30:tid 36] ssl_engine_io.c(2448): [client <client-ip>:58971] OpenSSL: I/O error, 5 bytes expected to write on BIO#7fdee0002d10 [mem: 7fdee000e633]" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805266 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): (4)Interrupted system call: polled with num=0 exit=0/0 conns=1 queues_timeout=4999969 timers_timeout=-1750665901805265" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805282 2025] [mpm_event:trace6] [pid 30:tid 83] event.c(1704): connections: 1 (clogged: 0 write-completion: 0 keep-alive: 1 lingering: 0 suspended: 0)" "2025-06-23T08:05:01.805Z","[Mon Jun 23 08:05:01.805286 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=5000000 queues_timeout=4999948 timers_timeout=-1750665901805286" "2025-06-23T08:05:02.179Z","<client-ip> - sommer [23/Jun/2025:07:56:07 +0000] ""POST /python_service/queryV2 HTTP/1.1"" 200 158" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807754 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): (70007)The timeout specified has expired: polled with num=0 exit=0/0 conns=1 queues_timeout=-2518 timers_timeout=-1750665906807752" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807777 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1973): queues maintenance with timeout=-2543" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807787 2025] [mpm_event:trace6] [pid 30:tid 83] event.c(842): [remote <client-ip>:58971] deferring close from state 0" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807790 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(2001): queues maintained with timeout=-1" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807804 2025] [mpm_event:trace6] [pid 30:tid 83] event.c(1704): connections: 1 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 1 suspended: 0)" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807806 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=-1 queues_timeout=-1750665906807806 timers_timeout=-1750665906807806" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807815 2025] [mpm_event:trace6] [pid 30:tid 53] event.c(1489): [client <client-ip>:58971] lingering close from state 5" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807857 2025] [ssl:trace6] [pid 30:tid 53] ssl_engine_io.c(219): [client <client-ip>:58971] bio_filter_out_write: 31 bytes" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807870 2025] [ssl:trace4] [pid 30:tid 53] ssl_engine_io.c(2428): [client <client-ip>:58971] OpenSSL: write 31/31 bytes to BIO#7fdee0002c50 [mem: 7fdeac003023] (BIO dump follows)" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807873 2025] [ssl:trace7] [pid 30:tid 53] ssl_engine_io.c(2325): [client <client-ip>:58971] +-------------------------------------------------------------------------+" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807878 2025] [ssl:trace7] [pid 30:tid 53] ssl_engine_io.c(2362): [client <client-ip>:58971] | 0000: 15 03 03 00 1a e1 a8 f3-1f 7d 77 7c 05 19 ac 29 .........}w|...) |" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807889 2025] [ssl:trace7] [pid 30:tid 53] ssl_engine_io.c(2362): [client <client-ip>:58971] | 0010: 44 d0 fa 38 77 71 a7 54-35 57 bd ad 56 b8 19 D..8wq.T5W..V.. |" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807891 2025] [ssl:trace7] [pid 30:tid 53] ssl_engine_io.c(2367): [client <client-ip>:58971] +-------------------------------------------------------------------------+" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807894 2025] [ssl:trace6] [pid 30:tid 53] ssl_engine_io.c(154): [client <client-ip>:58971] bio_filter_out_write: flush" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807926 2025] [core:trace6] [pid 30:tid 53] core_filters.c(828): [client <client-ip>:58971] writev_nonblocking: 31/31" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807937 2025] [ssl:trace3] [pid 30:tid 53] ssl_engine_kernel.c(2220): [client <client-ip>:58971] OpenSSL: Write: SSL negotiation finished successfully" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807941 2025] [ssl:trace6] [pid 30:tid 53] ssl_engine_io.c(154): [client <client-ip>:58971] bio_filter_out_write: flush" "2025-06-23T08:05:06.807Z","[Mon Jun 23 08:05:06.807944 2025] [ssl:debug] [pid 30:tid 53] ssl_engine_io.c(1150): [client <client-ip>:58971] AH02001: Connection closed to child 74 with standard shutdown (server someservice.de:443)" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808010 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): (4)Interrupted system call: polled with num=0 exit=0/0 conns=1 queues_timeout=1999972 timers_timeout=-1750665906808010" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808019 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=2000000 queues_timeout=1999963 timers_timeout=-1750665906808019" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808340 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): polled with num=1 exit=0/0 conns=1 queues_timeout=1999642 timers_timeout=-1750665906808340" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808358 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=2000000 queues_timeout=1999624 timers_timeout=-1750665906808358" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808368 2025] [mpm_event:trace6] [pid 30:tid 61] event.c(1489): [client <client-ip>:58971] lingering close from state 7" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808376 2025] [mpm_event:trace6] [pid 30:tid 61] event.c(872): [client <client-ip>:58971] closing connection from state 7" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808379 2025] [mpm_event:trace8] [pid 30:tid 61] event.c(544): closing socket 17/7fdeebd980b0 from close_connection:875" "2025-06-23T08:05:06.808Z","[Mon Jun 23 08:05:06.808393 2025] [mpm_event:trace8] [pid 30:tid 61] event.c(789): [client <client-ip>:58971] cleanup connection from state 7" "2025-06-23T08:05:08.810Z","[Mon Jun 23 08:05:08.810398 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): (70007)The timeout specified has expired: polled with num=0 exit=0/0 conns=0 queues_timeout=-2413 timers_timeout=-1750665908810395" "2025-06-23T08:05:08.810Z","[Mon Jun 23 08:05:08.810436 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1973): queues maintenance with timeout=-2454" "2025-06-23T08:05:08.810Z","[Mon Jun 23 08:05:08.810443 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(2001): queues maintained with timeout=-1" "2025-06-23T08:05:08.810Z","[Mon Jun 23 08:05:08.810447 2025] [mpm_event:trace6] [pid 30:tid 83] event.c(1704): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)" "2025-06-23T08:05:08.810Z","[Mon Jun 23 08:05:08.810452 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=-1 queues_timeout=-1750665908810451 timers_timeout=-1750665908810451" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295204 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1798): polled with num=1 exit=0/0 conns=0 queues_timeout=-1750665909295201 timers_timeout=-1750665909295201" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295212 2025] [mpm_event:trace7] [pid 29:tid 84] event.c(1798): polled with num=1 exit=0/0 conns=0 queues_timeout=10421374 timers_timeout=-1750665909295210" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295252 2025] [mpm_event:trace7] [pid 30:tid 83] event.c(1778): polling with timeout=-1 queues_timeout=-1750665909295252 timers_timeout=-1750665909295252" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295269 2025] [mpm_event:trace6] [pid 29:tid 84] event.c(1704): connections: 0 (clogged: 0 write-completion: 0 keep-alive: 0 lingering: 0 suspended: 0)" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295275 2025] [mpm_event:trace7] [pid 29:tid 84] event.c(1778): polling with timeout=10422000 queues_timeout=10421309 timers_timeout=-1750665909295275" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295340 2025] [ssl:trace2] [pid 29:tid 70] ssl_engine_rand.c(125): Server: Seeding PRNG with 656 bytes of entropy" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295613 2025] [socache_shmcb:debug] [pid 29:tid 70] mod_socache_shmcb.c(545): AH00835: socache_shmcb_retrieve (0x07 -> subcache 7)" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295622 2025] [socache_shmcb:debug] [pid 29:tid 70] mod_socache_shmcb.c(929): AH00851: shmcb_subcache_retrieve found no match" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295625 2025] [socache_shmcb:debug] [pid 29:tid 70] mod_socache_shmcb.c(556): AH00836: leaving socache_shmcb_retrieve successfully" "2025-06-23T08:05:09.295Z","[Mon Jun 23 08:05:09.295628 2025] [ssl:trace2] [pid 29:tid 70] ssl_engine_kernel.c(2058): Inter-Process Session Cache: request=GET status=MISSED id=07ee34a6580badff1e74a55dae0a23423c8263dc7b7e256af5519df8d7eb567f (session renewal)" "2025-06-23T08:05:09.342Z","[Mon Jun 23 08:05:09.342211 2025] [mpm_event:trace7] [pid 29:tid 84] event.c(1798): polled with num=1 exit=0/0 conns=1 queues_timeout=10374374 timers_timeout=-1750665909342210" "2025-06-23T08:05:09.342Z","[Mon Jun 23 08:05:09.342233 2025] [mpm_event:trace7] [pid 29:tid 84] event.c(1778): polling with timeout=10375000 queues_timeout=10374351 timers_timeout=-1750665909342233" "2025-06-23T08:05:09.342Z","[Mon Jun 23 08:05:09.342262 2025] [mpm_event:trace8] [pid 29:tid 77] event.c(544): closing socket 17/7fdee87900b0 from close_connection:875" -- You received this message because you are subscribed to the Google Groups "modwsgi" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion visit https://groups.google.com/d/msgid/modwsgi/8b12cf75-301d-4e0e-8a41-c239a89885c5n%40googlegroups.com.
