httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Russell, Scott" <Scott.Russ...@netapp.com>
Subject Re: mod_proxy_wstunnel frame opcode 12 on disconnect
Date Sat, 05 Oct 2013 17:46:21 GMT
Jim,

My same thought.

On Windows with 2.4.6, yes according to my coworker. I want to double check it though though
to confirm. I'm working on a 2.4.6 build for RHEL5 to test along side the 2.2.x back port.

--
Scott Russell
"The biggest human temptation is to settle for too little." -- Thomas Merton

> On Oct 5, 2013, at 9:02 AM, "Jim Jagielski" <jim@jaguNET.com> wrote:
> 
> 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