https://bz.apache.org/bugzilla/show_bug.cgi?id=65886
Bug ID: 65886
Summary: Regression: Reverse proxy with websocket forceing 60
second timeout regardless of config
Product: Apache httpd-2
Version: 2.4.51
Hardware: PC
OS: Mac OS X 10.1
Status: NEW
Severity: normal
Priority: P2
Component: mod_proxy
Assignee: [email protected]
Reporter: [email protected]
Target Milestone: ---
We have a reverse proxy from Apache to a Tomcat instance. Apache is configured
like this:
# Proxy tomcat
SetEnv proxy-initial-not-pooled
ProxyRequests Off
ProxyPreserveHost On
# Set timeout higher than Vaadin's "heartbeatInterval"
ProxyTimeout 300
# Proxy "/pcom" through to tomcat (Vaadin application)
ProxyPass /pcom/
http://127.0.0.1:8080/pcom/ retry=0
ProxyPassReverse /pcom/
http://127.0.0.1:8080/pcom/
#ProxyPassReverseCookieDomain 127.0.0.1:8080 SERVERNAME
#ProxyPassReverseCookiePath /pcom /pcom
# Proxy "/VAADIN" through to tomcat (Vaadin application)
ProxyPass /VAADIN/
http://127.0.0.1:8080/VAADIN/ retry=0
ProxyPassReverse /VAADIN/
http://127.0.0.1:8080/VAADIN/
# Proxy "/static" through to tomcat
ProxyPass /static/
http://127.0.0.1:8080/static/ retry=0
ProxyPassReverse /static/
http://127.0.0.1:8080/static/
# Proxy "/api" through to tomcat (REST API)
ProxyPass /api/
http://127.0.0.1:8080/ws/api/ retry=0
ProxyPassReverse /api/
http://127.0.0.1:8080/ws/api/
# Make websocket requests work properly for the above mappings as well
RewriteEngine On
RewriteCond %{HTTP:Upgrade} websocket [NC]
RewriteCond %{HTTP:Connection} upgrade [NC]
RewriteRule ^/pcom/ "ws://127.0.0.1:8080%{REQUEST_URI}" [P]
RewriteCond %{HTTP:Upgrade} websocket [NC]
RewriteCond %{HTTP:Connection} upgrade [NC]
RewriteRule ^/VAADIN/ "ws://127.0.0.1:8080%{REQUEST_URI}" [P]
RewriteCond %{HTTP:Upgrade} websocket [NC]
RewriteCond %{HTTP:Connection} upgrade [NC]
RewriteRule ^/static/ "ws://127.0.0.1:8080%{REQUEST_URI}" [P]
RewriteCond %{HTTP:Upgrade} websocket [NC]
RewriteCond %{HTTP:Connection} upgrade [NC]
RewriteRule ^/api/ "ws://127.0.0.1:8080%{REQUEST_URI}" [P]
Note that ProxyTimeout is set to 5 minutes because the client web application
only polls for new data every ~3 minutes.
This has worked for a long time and most recently worked fine with Apache
version 2.4.43. After upgrading to 2.4.51, we started getting disconnects in
the web application. So something was broken in a version in the range (2.4.43,
2.4.51].
After turning up the logging level, it became apparent that the proxy timeout
being used in 2.4.51 was actually 60 seconds instead of 5 minutes, even though
our config has not changed.
You can see it happen here. Note the line "proxy: websocket: tunnel running
(timeout 60.000000)" at time 16:28:11.114445, then the timeout occurring 60
seconds after "AH10213: proxy: websocket: polling timed out (client=31,
origin=31)":
[Tue Feb 15 16:28:11.111553 2022] [proxy_wstunnel:trace5] [pid 8825]
mod_proxy_wstunnel.c(340): [client 127.0.0.1:47232] handler fallback
[Tue Feb 15 16:28:11.111555 2022] [proxy_http:trace1] [pid 8825]
mod_proxy_http.c(1875): [client 127.0.0.1:47232] HTTP: serving URL
ws://127.0.0.1:8080/pcom/PUSH?v-uiId=4&v-pushId=7f29d183-3c6a-4c8c-b672-001261fc162f&X-Atmosphere-tracking-id=0&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=websocket&X-Atmosphere-TrackMessageSize=true&Content-Type=application/json;%20charset=UTF-8&X-atmo-protocol=true
[Tue Feb 15 16:28:11.111561 2022] [proxy:debug] [pid 8825]
proxy_util.c(2588): [client 127.0.0.1:47232] AH00944: connecting
ws://127.0.0.1:8080/pcom/PUSH?v-uiId=4&v-pushId=7f29d183-3c6a-4c8c-b672-001261fc162f&X-Atmosphere-tracking-id=0&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=websocket&X-Atmosphere-TrackMessageSize=true&Content-Type=application/json;%20charset=UTF-8&X-atmo-protocol=true
to 127.0.0.1:8080
[Tue Feb 15 16:28:11.111580 2022] [proxy:debug] [pid 8825]
proxy_util.c(2811): [client 127.0.0.1:47232] AH00947: connected
/pcom/PUSH?v-uiId=4&v-pushId=7f29d183-3c6a-4c8c-b672-001261fc162f&X-Atmosphere-tracking-id=0&X-Atmosphere-Framework=2.2.13.vaadin5-javascript&X-Atmosphere-Transport=websocket&X-Atmosphere-TrackMessageSize=true&Content-Type=application/json;%20charset=UTF-8&X-atmo-protocol=true
to 127.0.0.1:8080
[Tue Feb 15 16:28:11.114299 2022] [proxy_http:trace3] [pid 8825]
mod_proxy_http.c(1198): [client 127.0.0.1:47232] Status from backend: 101
[Tue Feb 15 16:28:11.114321 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(820): [client 127.0.0.1:47232] Headers received from backend:
[Tue Feb 15 16:28:11.114325 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(842): [client 127.0.0.1:47232] Upgrade: websocket
[Tue Feb 15 16:28:11.114331 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(842): [client 127.0.0.1:47232] Connection: upgrade
[Tue Feb 15 16:28:11.114335 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(842): [client 127.0.0.1:47232] Sec-WebSocket-Accept:
BBZpglr2TI0qkORtYXDeNDu3PN4=
[Tue Feb 15 16:28:11.114338 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(842): [client 127.0.0.1:47232] Sec-WebSocket-Extensions:
permessage-deflate
[Tue Feb 15 16:28:11.114341 2022] [proxy_http:trace4] [pid 8825]
mod_proxy_http.c(842): [client 127.0.0.1:47232] Date: Tue, 15 Feb 2022 22:28:10
GMT
[Tue Feb 15 16:28:11.114352 2022] [proxy_http:trace2] [pid 8825]
mod_proxy_http.c(1376): [client 127.0.0.1:47232] HTTP: received interim 101
response (policy: n/a)
[Tue Feb 15 16:28:11.114367 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(856): [client 127.0.0.1:47232] ssl_filter_write: 193 bytes
[Tue Feb 15 16:28:11.114392 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(215): [client 127.0.0.1:47232] bio_filter_out_write: 215 bytes
[Tue Feb 15 16:28:11.114403 2022] [ssl:trace4] [pid 8825]
ssl_engine_io.c(2370): [client 127.0.0.1:47232] OpenSSL: write 215/215 bytes to
BIO#56310e553f60 [mem: 56310e56aaa3]
[Tue Feb 15 16:28:11.114424 2022] [core:trace6] [pid 8825]
core_filters.c(812): [client 127.0.0.1:47232] writev_nonblocking: 215/215
[Tue Feb 15 16:28:11.114433 2022] [proxy_http:debug] [pid 8825]
mod_proxy_http.c(1480): [client 127.0.0.1:47232] AH10239: HTTP: tunneling
protocol websocket
[Tue Feb 15 16:28:11.114445 2022] [proxy:trace1] [pid 8825]
proxy_util.c(4874): [client 127.0.0.1:47232] AH10212: proxy: websocket: tunnel
running (timeout 60.000000)
[Tue Feb 15 16:28:11.114451 2022] [proxy:trace5] [pid 8825]
proxy_util.c(4980): [client 127.0.0.1:47232] proxy: websocket: client resume
writable
[Tue Feb 15 16:28:11.114458 2022] [proxy:trace2] [pid 8825]
proxy_util.c(4653): [client 127.0.0.1:47232]
ap_proxy_transfer_between_connections complete (from 127.0.0.1:8080)
[Tue Feb 15 16:28:11.114465 2022] [proxy:trace5] [pid 8825]
proxy_util.c(4980): [client 127.0.0.1:47232] proxy: websocket: origin resume
writable
[Tue Feb 15 16:28:11.114474 2022] [ssl:trace4] [pid 8825]
ssl_engine_io.c(2379): [client 127.0.0.1:47232] OpenSSL: I/O error, 5 bytes
expected to read on BIO#56310e557030 [mem: 56310e570b13]
[Tue Feb 15 16:28:11.114478 2022] [proxy:trace2] [pid 8825]
proxy_util.c(4653): (11)Resource temporarily unavailable: [client
127.0.0.1:47232] ap_proxy_transfer_between_connections complete (to
127.0.0.1:8080)
[Tue Feb 15 16:28:11.115073 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(856): [client 127.0.0.1:47232] ssl_filter_write: 44 bytes
[Tue Feb 15 16:28:11.115090 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(215): [client 127.0.0.1:47232] bio_filter_out_write: 66 bytes
[Tue Feb 15 16:28:11.115093 2022] [ssl:trace4] [pid 8825]
ssl_engine_io.c(2370): [client 127.0.0.1:47232] OpenSSL: write 66/66 bytes to
BIO#56310e553f60 [mem: 56310e56aaa3]
[Tue Feb 15 16:28:11.115110 2022] [core:trace6] [pid 8825]
core_filters.c(812): [client 127.0.0.1:47232] writev_nonblocking: 66/66
[Tue Feb 15 16:28:11.115117 2022] [proxy:trace2] [pid 8825]
proxy_util.c(4653): [client 127.0.0.1:47232]
ap_proxy_transfer_between_connections complete (from 127.0.0.1:8080)
[Tue Feb 15 16:29:11.124429 2022] [proxy:trace2] [pid 8825]
proxy_util.c(4896): [client 127.0.0.1:47232] AH10213: proxy: websocket: polling
timed out (client=31, origin=31)
[Tue Feb 15 16:29:11.124641 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(215): [client 127.0.0.1:47232] bio_filter_out_write: 24 bytes
[Tue Feb 15 16:29:11.124647 2022] [ssl:trace4] [pid 8825]
ssl_engine_io.c(2370): [client 127.0.0.1:47232] OpenSSL: write 24/24 bytes to
BIO#56310e553f60 [mem: 56310e56aaa3]
[Tue Feb 15 16:29:11.124650 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(156): [client 127.0.0.1:47232] bio_filter_out_write: flush
[Tue Feb 15 16:29:11.124671 2022] [core:trace6] [pid 8825]
core_filters.c(812): [client 127.0.0.1:47232] writev_nonblocking: 24/24
[Tue Feb 15 16:29:11.124675 2022] [ssl:trace3] [pid 8825]
ssl_engine_kernel.c(2223): [client 127.0.0.1:47232] OpenSSL: Write: SSL
negotiation finished successfully
[Tue Feb 15 16:29:11.124677 2022] [ssl:trace6] [pid 8825]
ssl_engine_io.c(156): [client 127.0.0.1:47232] bio_filter_out_write: flush
The web client displays the error "Disconnected from server" exactly 60 seconds
after connecting.
Where is this 60 seconds value coming from??
We tried adding "timeout=300" to the ProxyPass lines (even though this timeout
is supposed to alread default to ProxyTimeout) but that didn't help.
So we don't even have a workaround for this bug yet, other than downgrading.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
