I've attached annotated logs that show the issues I described. Both scenarios
have ProxyWebsocketAsync turned on. The first does not use the AsyncDelay and
shows how server messages stall and are not delivered until the client polls.
The second has ProxyWebsocketAsyncDelay set to 100. In that case, message
processing works properly, but threads are held open and there is no sign of
async processing.
Since my build and execution environment were somewhat non-standard, I repeated
all the tests today on stock Ubuntu 14.04, with a fresh checkout and build of
httpd and apr trunk code. The same results were observed.
- Steve
-----Original Message-----
________________________________________
From: Eric Covener [[email protected]]
Sent: July 17, 2014 9:15 PM
To: Apache HTTP Server Development List
Subject: Re: Question about async mod_proxy_wstunnel and threads
I am having trouble seeing it mis-behave. w/ Async and AsyncDelay, I am seeing
the expected trace messages and when I look at backtraces of httpd I can see
zero threads in wstunnel . If I send a server msg, I get it ASAP in the client
-- and then I see 1 thread in poll for the right couple of seconds
Can you grab trace at e.g.
LogLevel INFO proxy_wstunnel_module:trace8
And annotate the timing a bit for what you do in the client? Is it possible
you have an un-updated trunk from several weeks ago? There was an optimization
put in and backed out that might have broke some of these same things for a
very short window.
Apache config has:
ProxyWebsocketAsync ON
<VirtualHost _default_>
ProxyPass /ws/ ws://127.0.0.1:9000/ws/
</VirtualHost>
Start Apache. Webosocket server at 127.0.0.1:9000
[Fri Jul 18 16:13:05.874570 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1772): AH00925: initializing worker proxy:reverse shared
[Fri Jul 18 16:13:05.874590 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1814): AH00927: initializing worker proxy:reverse local
[Fri Jul 18 16:13:05.874637 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1849): AH00930: initialized pool in child 14918 for (*) min=0
max=64 smax=64
[Fri Jul 18 16:13:05.874646 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1772): AH00925: initializing worker ws://127.0.0.1:9000/ws/ shared
[Fri Jul 18 16:13:05.874653 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1814): AH00927: initializing worker ws://127.0.0.1:9000/ws/ local
[Fri Jul 18 16:13:05.874664 2014] [proxy:debug] [pid 14918:tid 139842560448256]
proxy_util.c(1849): AH00930: initialized pool in child 14918 for (127.0.0.1)
min=0 max=64 smax=64
[Fri Jul 18 16:13:05.874832 2014] [mpm_event:debug] [pid 14918:tid
139842442995456] event.c(2278): AH02471: start_threads: Using epoll
Connect client #1
[Fri Jul 18 16:13:32.257484 2014] [rewrite:trace1] [pid 14918:tid
139842434602752] mod_rewrite.c(481): [client 10.1.5.1:55995] 10.1.5.1 - -
[10.1.6.61/sid#1be5d08][rid#7f2f70004980/initial] pass through /ws/
[Fri Jul 18 16:13:32.257583 2014] [authz_core:debug] [pid 14918:tid
139842434602752] mod_authz_core.c(828): [client 10.1.5.1:55995] AH01628:
authorization result: granted (no directives)
[Fri Jul 18 16:13:32.257622 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842434602752] mod_proxy_wstunnel.c(221): [client 10.1.5.1:55995]
canonicalising URL //127.0.0.1:9000/ws/
[Fri Jul 18 16:13:32.257691 2014] [proxy:debug] [pid 14918:tid 139842434602752]
mod_proxy.c(1155): [client 10.1.5.1:55995] AH01143: Running scheme ws handler
(attempt 0)
[Fri Jul 18 16:13:32.257709 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842434602752] mod_proxy_wstunnel.c(474): [client 10.1.5.1:55995] AH02451:
serving URL ws://127.0.0.1:9000/ws/
[Fri Jul 18 16:13:32.257744 2014] [proxy:debug] [pid 14918:tid 139842434602752]
proxy_util.c(2129): AH00942: WS: has acquired connection for (127.0.0.1)
[Fri Jul 18 16:13:32.257756 2014] [proxy:debug] [pid 14918:tid 139842434602752]
proxy_util.c(2182): [client 10.1.5.1:55995] AH00944: connecting
ws://127.0.0.1:9000/ws/ to 127.0.0.1:9000
[Fri Jul 18 16:13:32.257864 2014] [proxy:debug] [pid 14918:tid 139842434602752]
proxy_util.c(2383): [client 10.1.5.1:55995] AH00947: connected /ws/ to
127.0.0.1:9000
[Fri Jul 18 16:13:32.257966 2014] [proxy:debug] [pid 14918:tid 139842434602752]
proxy_util.c(2897): AH00962: WS: connection complete to 127.0.0.1:9000
(127.0.0.1)
[Fri Jul 18 16:13:32.257983 2014] [proxy_wstunnel:trace2] [pid 14918:tid
139842434602752] mod_proxy_wstunnel.c(342): [client 10.1.5.1:55995] sending
request
[Fri Jul 18 16:13:32.258048 2014] [proxy_wstunnel:trace2] [pid 14918:tid
139842434602752] mod_proxy_wstunnel.c(360): [client 10.1.5.1:55995] setting up
poll()
[Fri Jul 18 16:13:32.258074 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842434602752] mod_proxy_wstunnel.c(65): [client 10.1.5.1:55995] AH02542:
Attempting to go async
[Fri Jul 18 16:13:32.261205 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842426210048] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55995] AH02445:
woke from poll(), i=1
[Fri Jul 18 16:13:32.261232 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842426210048] mod_proxy_wstunnel.c(88): [remote 10.1.5.1:55995] AH02446:
sock was readable
[Fri Jul 18 16:13:32.261285 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842426210048] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55995] AH02440:
read 257 bytes from sock
[Fri Jul 18 16:13:32.261327 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842426210048] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55995] AH02542:
Attempting to go async
[Fri Jul 18 16:13:32.261342 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842426210048] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55995]
proxy_wstunnel_callback suspend
Connect client #2
[Fri Jul 18 16:13:34.841344 2014] [rewrite:trace1] [pid 14918:tid
139842417817344] mod_rewrite.c(481): [client 10.1.5.1:55996] 10.1.5.1 - -
[10.1.6.61/sid#1be5d08][rid#7f2f6c004980/initial] pass through /ws/
[Fri Jul 18 16:13:34.841387 2014] [authz_core:debug] [pid 14918:tid
139842417817344] mod_authz_core.c(828): [client 10.1.5.1:55996] AH01628:
authorization result: granted (no directives)
[Fri Jul 18 16:13:34.841398 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842417817344] mod_proxy_wstunnel.c(221): [client 10.1.5.1:55996]
canonicalising URL //127.0.0.1:9000/ws/
[Fri Jul 18 16:13:34.841413 2014] [proxy:debug] [pid 14918:tid 139842417817344]
mod_proxy.c(1155): [client 10.1.5.1:55996] AH01143: Running scheme ws handler
(attempt 0)
[Fri Jul 18 16:13:34.841418 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842417817344] mod_proxy_wstunnel.c(474): [client 10.1.5.1:55996] AH02451:
serving URL ws://127.0.0.1:9000/ws/
[Fri Jul 18 16:13:34.841424 2014] [proxy:debug] [pid 14918:tid 139842417817344]
proxy_util.c(2129): AH00942: WS: has acquired connection for (127.0.0.1)
[Fri Jul 18 16:13:34.841429 2014] [proxy:debug] [pid 14918:tid 139842417817344]
proxy_util.c(2182): [client 10.1.5.1:55996] AH00944: connecting
ws://127.0.0.1:9000/ws/ to 127.0.0.1:9000
[Fri Jul 18 16:13:34.841435 2014] [proxy:debug] [pid 14918:tid 139842417817344]
proxy_util.c(2383): [client 10.1.5.1:55996] AH00947: connected /ws/ to
127.0.0.1:9000
[Fri Jul 18 16:13:34.841520 2014] [proxy:debug] [pid 14918:tid 139842417817344]
proxy_util.c(2897): AH00962: WS: connection complete to 127.0.0.1:9000
(127.0.0.1)
[Fri Jul 18 16:13:34.841533 2014] [proxy_wstunnel:trace2] [pid 14918:tid
139842417817344] mod_proxy_wstunnel.c(342): [client 10.1.5.1:55996] sending
request
[Fri Jul 18 16:13:34.841580 2014] [proxy_wstunnel:trace2] [pid 14918:tid
139842417817344] mod_proxy_wstunnel.c(360): [client 10.1.5.1:55996] setting up
poll()
[Fri Jul 18 16:13:34.841600 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842417817344] mod_proxy_wstunnel.c(65): [client 10.1.5.1:55996] AH02542:
Attempting to go async
[Fri Jul 18 16:13:34.843170 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842409424640] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55996] AH02445:
woke from poll(), i=1
[Fri Jul 18 16:13:34.843186 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842409424640] mod_proxy_wstunnel.c(88): [remote 10.1.5.1:55996] AH02446:
sock was readable
[Fri Jul 18 16:13:34.843229 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842409424640] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55996] AH02440:
read 257 bytes from sock
[Fri Jul 18 16:13:34.843261 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842409424640] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55996] AH02542:
Attempting to go async
[Fri Jul 18 16:13:34.843270 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842409424640] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55996]
proxy_wstunnel_callback suspend
Messages sent from either client #1 or #2 should be echoed back from the server
to both clients.
Send message from client #1 to server.
[Fri Jul 18 16:14:11.057256 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842401031936] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55995] AH02445:
woke from poll(), i=1
[Fri Jul 18 16:14:11.057308 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842401031936] mod_proxy_wstunnel.c(106): [remote 10.1.5.1:55995] AH02448:
client was readable
[Fri Jul 18 16:14:11.057366 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842401031936] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55995] AH02440:
read 10 bytes from client
[Fri Jul 18 16:14:11.084153 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842401031936] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55995] AH02542:
Attempting to go async
[Fri Jul 18 16:14:11.084169 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842401031936] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55995]
proxy_wstunnel_callback suspend
Message echoed back to client #1 only
[Fri Jul 18 16:14:11.084771 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842323216128] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55995] AH02445:
woke from poll(), i=1
[Fri Jul 18 16:14:11.084797 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842323216128] mod_proxy_wstunnel.c(88): [remote 10.1.5.1:55995] AH02446:
sock was readable
[Fri Jul 18 16:14:11.084830 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842323216128] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55995] AH02440:
read 6 bytes from sock
[Fri Jul 18 16:14:11.084859 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842323216128] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55995] AH02542:
Attempting to go async
[Fri Jul 18 16:14:11.084869 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842323216128] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55995]
proxy_wstunnel_callback suspend
[missing message to client #2]
30 seconds later, send message from client #2 to server. Message should be
echoed to client #1 and #2
First message processed is the missing message from server to client #2
[Fri Jul 18 16:14:40.945825 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55996] AH02445:
woke from poll(), i=2
[Fri Jul 18 16:14:40.945887 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(88): [remote 10.1.5.1:55996] AH02446:
sock was readable
[Fri Jul 18 16:14:40.945911 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55996] AH02440:
read 6 bytes from sock
Then the message from client #2 to the server
[Fri Jul 18 16:14:40.945976 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(106): [remote 10.1.5.1:55996] AH02448:
client was readable
[Fri Jul 18 16:14:40.946029 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55996] AH02440:
read 9 bytes from client
[Fri Jul 18 16:14:40.946083 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55996] AH02542:
Attempting to go async
[Fri Jul 18 16:14:40.946095 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842314823424] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55996]
proxy_wstunnel_callback suspend
And the reply from server to client #2. Missing message from server to client #1
[Fri Jul 18 16:14:40.946741 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842306430720] mod_proxy_wstunnel.c(79): [remote 10.1.5.1:55996] AH02445:
woke from poll(), i=1
[Fri Jul 18 16:14:40.946767 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842306430720] mod_proxy_wstunnel.c(88): [remote 10.1.5.1:55996] AH02446:
sock was readable
[Fri Jul 18 16:14:40.946817 2014] [proxy_wstunnel:debug] [pid 14918:tid
139842306430720] mod_proxy_wstunnel.c(288): [remote 10.1.5.1:55996] AH02440:
read 5 bytes from sock
[Fri Jul 18 16:14:40.946845 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842306430720] mod_proxy_wstunnel.c(65): [remote 10.1.5.1:55996] AH02542:
Attempting to go async
[Fri Jul 18 16:14:40.946856 2014] [proxy_wstunnel:trace1] [pid 14918:tid
139842306430720] mod_proxy_wstunnel.c(183): [remote 10.1.5.1:55996]
proxy_wstunnel_callback suspend
Apache config has:
ProxyWebsocketAsync ON
ProxyWebsocketAsyncDelay 100
<VirtualHost _default_>
ProxyPass /ws/ ws://127.0.0.1:9000/ws/
</VirtualHost>
Start Apache
[Fri Jul 18 17:37:19.034018 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1772): AH00925: initializing worker proxy:reverse shared
[Fri Jul 18 17:37:19.034043 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1814): AH00927: initializing worker proxy:reverse local
[Fri Jul 18 17:37:19.034113 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1849): AH00930: initialized pool in child 15435 for (*) min=0
max=64 smax=64
[Fri Jul 18 17:37:19.034126 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1772): AH00925: initializing worker ws://127.0.0.1:9000/ws/ shared
[Fri Jul 18 17:37:19.034133 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1814): AH00927: initializing worker ws://127.0.0.1:9000/ws/ local
[Fri Jul 18 17:37:19.034141 2014] [proxy:debug] [pid 15435:tid 139687082264320]
proxy_util.c(1849): AH00930: initialized pool in child 15435 for (127.0.0.1)
min=0 max=64 smax=64
[Fri Jul 18 17:37:19.034306 2014] [mpm_event:debug] [pid 15435:tid
139686964811520] event.c(2278): AH02471: start_threads: Using epoll
Connect client #1
[Fri Jul 18 17:37:35.590720 2014] [rewrite:trace1] [pid 15435:tid
139686948026112] mod_rewrite.c(481): [client 10.1.5.1:56118] 10.1.5.1 - -
[10.1.6.61/sid#115fd80][rid#7f0b3c004980/initial] pass through /ws/
[Fri Jul 18 17:37:35.590799 2014] [authz_core:debug] [pid 15435:tid
139686948026112] mod_authz_core.c(828): [client 10.1.5.1:56118] AH01628:
authorization result: granted (no directives)
[Fri Jul 18 17:37:35.590817 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(221): [client 10.1.5.1:56118]
canonicalising URL //127.0.0.1:9000/ws/
[Fri Jul 18 17:37:35.590867 2014] [proxy:debug] [pid 15435:tid 139686948026112]
mod_proxy.c(1155): [client 10.1.5.1:56118] AH01143: Running scheme ws handler
(attempt 0)
[Fri Jul 18 17:37:35.590880 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(474): [client 10.1.5.1:56118] AH02451:
serving URL ws://127.0.0.1:9000/ws/
[Fri Jul 18 17:37:35.590892 2014] [proxy:debug] [pid 15435:tid 139686948026112]
proxy_util.c(2129): AH00942: WS: has acquired connection for (127.0.0.1)
[Fri Jul 18 17:37:35.590898 2014] [proxy:debug] [pid 15435:tid 139686948026112]
proxy_util.c(2182): [client 10.1.5.1:56118] AH00944: connecting
ws://127.0.0.1:9000/ws/ to 127.0.0.1:9000
[Fri Jul 18 17:37:35.590948 2014] [proxy:debug] [pid 15435:tid 139686948026112]
proxy_util.c(2383): [client 10.1.5.1:56118] AH00947: connected /ws/ to
127.0.0.1:9000
[Fri Jul 18 17:37:35.591065 2014] [proxy:debug] [pid 15435:tid 139686948026112]
proxy_util.c(2897): AH00962: WS: connection complete to 127.0.0.1:9000
(127.0.0.1)
[Fri Jul 18 17:37:35.591081 2014] [proxy_wstunnel:trace2] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(342): [client 10.1.5.1:56118] sending
request
[Fri Jul 18 17:37:35.591141 2014] [proxy_wstunnel:trace2] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(360): [client 10.1.5.1:56118] setting up
poll()
[Fri Jul 18 17:37:35.593938 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56118] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:37:35.593959 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56118] AH02446:
sock was readable
[Fri Jul 18 17:37:35.593985 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56118] AH02440:
read 257 bytes from sock
(no longer see "Attempting to go async")
Connect client #2
[Fri Jul 18 17:37:38.918581 2014] [rewrite:trace1] [pid 15435:tid
139686956418816] mod_rewrite.c(481): [client 10.1.5.1:56119] 10.1.5.1 - -
[10.1.6.61/sid#115fd80][rid#7f0b34004980/initial] pass through /ws/
[Fri Jul 18 17:37:38.918630 2014] [authz_core:debug] [pid 15435:tid
139686956418816] mod_authz_core.c(828): [client 10.1.5.1:56119] AH01628:
authorization result: granted (no directives)
[Fri Jul 18 17:37:38.918643 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(221): [client 10.1.5.1:56119]
canonicalising URL //127.0.0.1:9000/ws/
[Fri Jul 18 17:37:38.918658 2014] [proxy:debug] [pid 15435:tid 139686956418816]
mod_proxy.c(1155): [client 10.1.5.1:56119] AH01143: Running scheme ws handler
(attempt 0)
[Fri Jul 18 17:37:38.918676 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(474): [client 10.1.5.1:56119] AH02451:
serving URL ws://127.0.0.1:9000/ws/
[Fri Jul 18 17:37:38.918684 2014] [proxy:debug] [pid 15435:tid 139686956418816]
proxy_util.c(2129): AH00942: WS: has acquired connection for (127.0.0.1)
[Fri Jul 18 17:37:38.918689 2014] [proxy:debug] [pid 15435:tid 139686956418816]
proxy_util.c(2182): [client 10.1.5.1:56119] AH00944: connecting
ws://127.0.0.1:9000/ws/ to 127.0.0.1:9000
[Fri Jul 18 17:37:38.918694 2014] [proxy:debug] [pid 15435:tid 139686956418816]
proxy_util.c(2383): [client 10.1.5.1:56119] AH00947: connected /ws/ to
127.0.0.1:9000
[Fri Jul 18 17:37:38.918765 2014] [proxy:debug] [pid 15435:tid 139686956418816]
proxy_util.c(2897): AH00962: WS: connection complete to 127.0.0.1:9000
(127.0.0.1)
[Fri Jul 18 17:37:38.918780 2014] [proxy_wstunnel:trace2] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(342): [client 10.1.5.1:56119] sending
request
[Fri Jul 18 17:37:38.918821 2014] [proxy_wstunnel:trace2] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(360): [client 10.1.5.1:56119] setting up
poll()
[Fri Jul 18 17:37:38.920771 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56119] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:37:38.920821 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56119] AH02446:
sock was readable
[Fri Jul 18 17:37:38.920839 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56119] AH02440:
read 257 bytes from sock
Send message from client #1 to server. Echoed back to both clients.
[Fri Jul 18 17:37:45.965772 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56118] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:37:45.965814 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(106): [client 10.1.5.1:56118] AH02448:
client was readable
[Fri Jul 18 17:37:45.965842 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56118] AH02440:
read 10 bytes from client
[Fri Jul 18 17:37:45.966376 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56118] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:37:45.966390 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56118] AH02446:
sock was readable
[Fri Jul 18 17:37:45.966404 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56118] AH02440:
read 6 bytes from sock
[Fri Jul 18 17:37:45.966473 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56119] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:37:45.966486 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56119] AH02446:
sock was readable
[Fri Jul 18 17:37:45.966514 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56119] AH02440:
read 6 bytes from sock
Send message from client #2 to server. Again echoed back to both clients, but
no indication that it is going async.
[Fri Jul 18 17:38:26.806467 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56119] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:38:26.806512 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(106): [client 10.1.5.1:56119] AH02448:
client was readable
[Fri Jul 18 17:38:26.806541 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56119] AH02440:
read 9 bytes from client
[Fri Jul 18 17:38:26.807038 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56118] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:38:26.807053 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56118] AH02446:
sock was readable
[Fri Jul 18 17:38:26.807069 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686948026112] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56118] AH02440:
read 5 bytes from sock
[Fri Jul 18 17:38:26.807151 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(79): [client 10.1.5.1:56119] AH02445:
woke from poll(), i=1
[Fri Jul 18 17:38:26.807164 2014] [proxy_wstunnel:trace1] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(88): [client 10.1.5.1:56119] AH02446:
sock was readable
[Fri Jul 18 17:38:26.807173 2014] [proxy_wstunnel:debug] [pid 15435:tid
139686956418816] mod_proxy_wstunnel.c(288): [client 10.1.5.1:56119] AH02440:
read 5 bytes from sock
