httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jim Jagielski <...@jaguNET.com>
Subject Re: mod_proxy_wstunnel frame opcode 12 on disconnect
Date Sat, 05 Oct 2013 13:01:10 GMT
It would be useful to know if this happens with 2.4.x...

On Oct 4, 2013, at 8:06 PM, "Russell, Scott" <Scott.Russell@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.Russell@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
>> 
> 


Mime
View raw message