How do I go about enabling debug logging in Mongrel then?
There doesn't appear to be any mention of it in the docco. There is a
post on the mail list abour USR1 logging?
On 13 June 2012 19:39, Matt Hoyle <[email protected]
<mailto:[email protected]>> wrote:
Hello,
I've messing about with Plack::Handler::Mongrel2 plugged into a
Dancer application and obviously Mongrel2.
Under JMeter load testing hitting the same URL repeatedly I am
getting into a situation where the front end requests start
receiving a "java.net.SocketTimeoutException: Read timed out"
error. The tests are doing a repeated request "GET
http://localhost:6767/app/polamaolaolaolaoaloalaoalaoalaoalaoalaoalaaoalaoaalaoalaoalaoa?j=8&t=1";
Mongrel will always produce the following error for a failed request:
[INFO] (src/mongrel2.c:343) Starting Mongrel2/1.7.5.
<http://1.7.5.> Copyright (C) Zed A. Shaw. Licensed BSD.
[INFO] (src/server.c:272) Starting server on port 6767
[INFO] (src/task/fd.c:151) MAX limits.fdtask_stack=102400
[INFO] (src/superpoll.c:102) Allowing for 256 hot and 768 idle
file descriptors (dividend was 4)
[INFO] (src/handler.c:209) MAX allowing limits.handler_targets=128
[INFO] (src/handler.c:285) Binding handler PUSH socket
tcp://127.0.0.1:9998 <http://127.0.0.1:9998> with identity:
E80576A8-AC0B-11DF-A841-3D4975AD5E34
[INFO] (src/handler.c:311) Binding listener SUB socket
tcp://127.0.0.1:9999 <http://127.0.0.1:9999> subscribed to:
D807E984-AC0B-11DF-979C-3C4975AD5E34
[INFO] (src/control.c:401) Setting up control socket in at
ipc://run/control
*[ERROR] (src/register.c:214: errno: Resource temporarily
unavailable) Nothing registered under id 0.*
*[ERROR] (src/register.c:199: errno: None) Invalid FD given
for exists check*
*
*
Mongrel finish's the tcp connection to the http client after the
zmq message is sent to the Plank back end:
http client -> Mongrel 6767
Mongrel -> plank 9998
*This is when the problem occurs and client http connection is
finished*
Plank -> Mongrel 9999
Mongrel -> Client 'high port'
sudo tcpdump -n -i lo -s 158 -p tcp port 6767 or tcp port 9999
or tcp port 9998
18:11:11.991287 IP 127.0.0.1.52686 > 127.0.0.1.6767: Flags
[P.], seq 30808:31037, ack 79381, win 384, options [nop,nop,TS
val 41369964 ecr 41369963], length 229
18:11:11.991470 IP 127.0.0.1.9998 > 127.0.0.1.55744: Flags
[P.], seq 17675:18211, ack 3, win 256, options [nop,nop,TS val
41369964 ecr 41369955], length 536
18:11:11.991480 IP 127.0.0.1.55744 > 127.0.0.1.9998: Flags
[.], ack 18211, win 384, options [nop,nop,TS val 41369964 ecr
41369959], length 0
18:11:12.001689 IP 127.0.0.1.52686 > 127.0.0.1.6767: Flags
*[F.]*, seq 31037, ack 79381, win 384, options [nop,nop,TS val
41369966 ecr 41369963], length 0
18:11:12.001759 IP 127.0.0.1.6767 > 127.0.0.1.52686: Flags
*[F.]*, seq 79381, ack 31038, win 384, options [nop,nop,TS val
41369966 ecr 41369964], length 0
18:11:12.001772 IP 127.0.0.1.52686 > 127.0.0.1.6767: Flags
[.], ack 79382, win 384, options [nop,nop,TS val 41369966 ecr
41369966], length 0
18:11:12.010615 IP 127.0.0.1.50171 > 127.0.0.1.9999: Flags
[P.], seq 21123:21763, ack 3, win 257, options [nop,nop,TS val
41369968 ecr 41369956], length 640
18:11:12.010655 IP 127.0.0.1.9999 > 127.0.0.1.50171: Flags
[.], ack 21763, win 384, options [nop,nop,TS val 41369968 ecr
41369960], length 0
Whereas it normally looks like this:
18:11:11.968949 IP 127.0.0.1.52686 > 127.0.0.1.6767: Flags
[P.], seq 29663:29892, ack 76441, win 384, options [nop,nop,TS
val 41369958 ecr 41369958], length 229
18:11:11.969095 IP 127.0.0.1.9998 > 127.0.0.1.55742: Flags
[P.], seq 17137:17673, ack 3, win 256, options [nop,nop,TS val
41369958 ecr 41369954], length 536
18:11:11.971890 IP 127.0.0.1.50169 > 127.0.0.1.9999: Flags
[P.], seq 20483:21123, ack 3, win 257, options [nop,nop,TS val
41369959 ecr 41369955], length 640
18:11:11.972006 IP 127.0.0.1.6767 > 127.0.0.1.52686: Flags
[P.], seq 76441:77029, ack 29892, win 384, options [nop,nop,TS
val 41369959 ecr 41369958], length 588
18:11:11.973493 IP 127.0.0.1.52686 > 127.0.0.1.6767: Flags
[P.], seq 29892:30121, ack 77029, win 384, options [nop,nop,TS
val 41369959 ecr 41369959], length 229
The only thing of note I found in Plack::Handler::Mongrel2 at the
same time as the errors were undefined variable errors, but they
were all related to the METHOD=JSON disconnect message being sent
out after this issue has occured.
I can increase the the frequency of the errors by increasing the
debug logging on the Perl/Plack side of things so I believe it's
something in the back end but I'm at a loss at the moment as to
what could be causing it. It happens with or without multiple
threads or a single thread at each http client and plack levels.
Any ideas on where to look next would be appreciated.
Cheers,
Matt
