httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Russell, Scott" <Scott.Russ...@netapp.com>
Subject mod_proxy_wstunnel frame opcode 12 on disconnect
Date Fri, 04 Oct 2013 22:07:37 GMT
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<http://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