It would be useful to know if this happens with 2.4.x... On Oct 4, 2013, at 8:06 PM, "Russell, Scott" <scott.russ...@netapp.com> wrote:
> Continuing to look at this, I can show a packet trace where everything looks > normal between the httpd and the node.js server on close. But if I do the > same trace between the httpd and the browser I can see malformed a websocket > packet when the stream closes. > > I'm not sure what (if anything) in the mod_proxy_wstunnel would be causing a > malformed websocket packet to be sent when the connection closes. > > -- > Scott Russell > Software Architect > Customer Success Services > (919) 476-8813 > > On Oct 4, 2013, at 6:07 PM, "Russell, Scott" <scott.russ...@netapp.com> wrote: > >> I'm wondering if anyone else is seeing an frame opcode 12 on >> socket.disconnect() when using socket.io with mod_proxy_wstunnel. I have a >> fairly simple replication setup that I'm investigating. >> >> I'm using apache 2.2.25 with a backported mod_proxy_wstunnel patch from >> 2.4.6. I'm seeing an unexpected frame opcode12 frame when the client or the >> server drops the websocket. I can only replicate this when going through the >> mod_http_wstunnel. If I change my client code to talk directly to the >> websocket on port 8001 I don't see the opcode 12 frame. >> >> Here is what my proxy config looks like: >> >> <VirtualHost gnu.corp.netapp.com:80> >> LogLevel debug >> >> ProxyPass /socket.io/1/websocket ws://localhost:8001/socket.io/1/websocket >> ProxyPassReverse /socket.io/1/websocket >> ws://localhost:8001/socket.io/1/websocket >> >> ProxyPass /socket.io/ http://localhost:8001/socket.io/ >> ProxyPassReverse /socket.io/ http://localhost:8001/socket.io/ >> >> ProxyPass / http://localhost:8080/ >> ProxyPassReverse / http://localhost:8080/ >> </VirtualHost> >> >> # apache static content >> <VirtualHost localhost:8080> >> DocumentRoot /var/www/static >> <Directory /> >> Allow from all >> </Directory> >> </VirtualHost> >> >> Here is what it looks like in Chrome Dev Tools for the websocket connection: >> >> Data Length Time >> ------------------------------------------------------------------ >> Unrecognized frame opcode: 12 29 5:55:55 PM >> 0:: 3 5:55:55 PM >> Connection Close Frame (Opcode 8, mask) 0 5:55:55 PM >> 0:: 3 5:55:55 PM >> 5:::{"name":"news","args":[{"hello":"world"}]} 46 5:55:55 PM >> 3:::Client connected 20 5:55:55 PM >> 1:: 3 5:55:55 PM >> >> >> >> error_log doesn't seem to be very interesting here: >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: >> canonicalising URL //localhost:8080/ >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(1513): [client >> 10.63.231.202] proxy: http: found worker http://localhost:8080/ for >> http://localhost:8080/ >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy.c(1036): Running scheme http >> handler (attempt 0) >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(1974): proxy: HTTP: >> serving URL http://localhost:8080/ >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2018): proxy: HTTP: has >> acquired connection for (localhost) >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2074): proxy: connecting >> http://localhost:8080/ to localhost:8080 >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2200): proxy: connected / to >> localhost:8080 >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2451): proxy: HTTP: fam 2 >> socket created to connect to localhost >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2583): proxy: HTTP: >> connection complete to 127.0.0.1:8080 (localhost) >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(1744): proxy: start body >> send >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(1848): proxy: end body >> send >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2036): proxy: HTTP: has >> released connection for (localhost) >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: >> canonicalising URL //localhost:8001/socket.io/socket.io.js >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(1513): [client >> 10.63.231.202] proxy: http: found worker http://localhost:8001/socket.io/ >> for http://localhost:8001/socket.io/socket.io.js, referer: >> http://gnu.corp.netapp.com/ >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy.c(1036): Running scheme http >> handler (attempt 0) >> [Fri Oct 04 16:47:09 2013] [debug] mod_proxy_http.c(1974): proxy: HTTP: >> serving URL http://localhost:8001/socket.io/socket.io.js >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2018): proxy: HTTP: has >> acquired connection for (localhost) >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2074): proxy: connecting >> http://localhost:8001/socket.io/socket.io.js to localhost:8001 >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2200): proxy: connected >> /socket.io/socket.io.js to localhost:8001 >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2451): proxy: HTTP: fam 2 >> socket created to connect to localhost >> [Fri Oct 04 16:47:09 2013] [debug] proxy_util.c(2583): proxy: HTTP: >> connection complete to 127.0.0.1:8001 (localhost) >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(1744): proxy: start body >> send >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(1848): proxy: end body >> send >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(2036): proxy: HTTP: has >> released connection for (localhost) >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: >> canonicalising URL //localhost:8001/socket.io/1/ >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(1513): [client >> 10.63.231.202] proxy: http: found worker http://localhost:8001/socket.io/ >> for http://localhost:8001/socket.io/1/?t=1380923754926, referer: >> http://gnu.corp.netapp.com/ >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy.c(1036): Running scheme http >> handler (attempt 0) >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(1974): proxy: HTTP: >> serving URL http://localhost:8001/socket.io/1/?t=1380923754926 >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(2018): proxy: HTTP: has >> acquired connection for (localhost) >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(2074): proxy: connecting >> http://localhost:8001/socket.io/1/?t=1380923754926 to localhost:8001 >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(2200): proxy: connected >> /socket.io/1/?t=1380923754926 to localhost:8001 >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(1744): proxy: start body >> send >> [Fri Oct 04 16:47:10 2013] [debug] mod_proxy_http.c(1848): proxy: end body >> send >> [Fri Oct 04 16:47:10 2013] [debug] proxy_util.c(2036): proxy: HTTP: has >> released connection for (localhost) >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(51): [client >> 10.63.231.202] canonicalising URL >> //localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(1513): [client >> 10.63.231.202] proxy: ws: found worker >> ws://localhost:8001/socket.io/1/websocket for >> ws://localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy.c(1036): Running scheme ws >> handler (attempt 0) >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_http.c(1964): proxy: HTTP: >> declining URL ws://localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_scgi.c(508): [client >> 10.63.231.202] proxy: SCGI: declining URL >> ws://localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(331): [client >> 10.63.231.202] AH02451: serving URL >> ws://localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2018): proxy: WS: has >> acquired connection for (localhost) >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2074): proxy: connecting >> ws://localhost:8001/socket.io/1/websocket/Xjww5htx3meYyb2YMS-T to >> localhost:8001 >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2200): proxy: connected >> /socket.io/1/websocket/Xjww5htx3meYyb2YMS-T to localhost:8001 >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2387): proxy: WS: backend >> socket is disconnected. >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2451): proxy: WS: fam 2 >> socket created to connect to localhost >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2583): proxy: WS: connection >> complete to 127.0.0.1:8001 (localhost) >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(192): [client >> 10.63.231.202] sending request >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(210): [client >> 10.63.231.202] setting up poll() >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(252): [client >> 10.63.231.202] AH02445: woke from poll(), i=1 >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(261): [client >> 10.63.231.202] AH02446: sock was readable >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(252): [client >> 10.63.231.202] AH02445: woke from poll(), i=1 >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(277): [client >> 10.63.231.202] AH02448: client was readable >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(252): [client >> 10.63.231.202] AH02445: woke from poll(), i=1 >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(277): [client >> 10.63.231.202] AH02448: client was readable >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(252): [client >> 10.63.231.202] AH02445: woke from poll(), i=1 >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(261): [client >> 10.63.231.202] AH02446: sock was readable >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(252): [client >> 10.63.231.202] AH02445: woke from poll(), i=1 >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(261): [client >> 10.63.231.202] AH02446: sock was readable >> [Fri Oct 04 16:47:11 2013] [debug] mod_proxy_wstunnel.c(294): [client >> 10.63.231.202] finished with poll() - cleaning up >> [Fri Oct 04 16:47:11 2013] [debug] proxy_util.c(2036): proxy: WS: has >> released connection for (localhost) >> >> -- >> Scott Russell >> Software Architect >> Customer Success Services >> (919) 476-8813 >> >
