librelist archives

Re: [mongrel2] Thousands of @* requests on my handlers

From:

Loic d'Anterroches

Date:

2011-02-26 @ 15:56

Again, sorry for the noise...

Everything is explained in src/handler.c line 126. Basically, even if
the PATH is @*, it is the handler sending the answer back to a dead
connection which is getting the disconnect message back.

So, now, I let my framework handle the disconnect request but if it
failed to handle it, I pay attention to not send back an answer to Mongrel2.

loïc

On 2011-02-26 15:41, Loic d'Anterroches wrote:
> Again,
> 
> ok, I was able to reproduce, that is, I waited, had lunch, a nap, came
> back and got my mongrel saturating my handler with disconnect messages.
> Within about 2 minutes, my logs got 558995 requests from just two
> connections:
> 
> $ cat /tmp/income.log | wc -l
> 558995
> $ cat /tmp/income.log | sort | uniq
> 
["ac013378-26d3-4cf2-a634-757df533092d","11320","@*",{"METHOD":"JSON"},{"type":"disconnect"}]
> 
["ac013378-26d3-4cf2-a634-757df533092d","11529","@*",{"METHOD":"JSON"},{"type":"disconnect"}]
> 
> I suppose, I do something plain wrong. When I get this request to my
> handler I answer with an HTTP 404 error. Which is most likely triggering
> a "I told you it was closed, I tell you again". Snowball effect.
> 
> I basically did not follow this:
> http://mongrel2.org/doc/tip/docs/manual/book.wiki#x1-740005.4
> 
>     req = conn.recv()
> 
>     if req.is_disconnect():
>         print "DISCONNECT"
>         continue
> 
> do nothing on disconnect requests.
> 
> Right?
> loïc
> 
> 
> 
> 
> 
> On 2011-02-26 11:37, Loic d'Anterroches wrote:
>> Hello.
>>
>> I am a bit unsettled with an issue I had yesterday and this night.
>> Yesterday, during the day, running the stock 1.5 release, I found that
>> my handlers were saturated by Mongrel2.
>>
>> Basically Mongrel2 was sending up to 8000 req/s to my handlers. At the
>> handler level, I just dumped the sender id, connection id, path and
>> headers to a log file. This is a couple of minutes sampling:
>>
>> $ tail -5 income.log
>> ["ac013378-26d3-4cf2-a634-757df533092d","52405","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","54100","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","57665","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","56138","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","52981","@*",{"METHOD":"JSON"}]
>> $ cat income.log | wc -l
>> 550966
>> $ ls -lh income.log
>> -rw-r--r-- 1 www-data www-data 38M 2011-02-25 21:37 income.log
>> $ sort income.log | uniq | wc -l
>> 116
>> $ cat income.log.sorted | uniq | grep -v PATH
>> ["ac013378-26d3-4cf2-a634-757df533092d","48892","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","51849","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","52405","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","52981","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","53003","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","53282","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","53406","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","54100","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","56138","@*",{"METHOD":"JSON"}]
>> ["ac013378-26d3-4cf2-a634-757df533092d","57665","@*",{"METHOD":"JSON"}]
>>
>> So only 10 connections, so, next step, checking against the log files
>> for theses connections:
>>
>> $ cat logs/access.log | grep 57665
>> dist.photon-project.com,178.33.145.147,57665,1298577164,/,HTTP/1.0,200,2920
>> dist.photon-project.com,178.33.145.147,57665,1298673573,/,HTTP/1.0,200,3040
>> photon-project.com,178.33.145.147,57665,1298673705,/about,HTTP/1.0,200,0
>>
>> Oh, interesting, each time, the ip is 178.33.145.147, another server I
>> have that I have been using to run siege against the running server.
>> this night, I had the same issue with after upgrading to the latest
>> "trunk" of Mongrel2 and after running this siege from this other server:
>>
>> $ siege -c4 -t5S  http://www.photon-project.com/about
>> ** SIEGE 2.68
>> ** Preparing 4 concurrent users for battle.
>> The server is now under siege...
>> Lifting the server siege..      done.
>> Transactions:		       10867 hits
>> Availability:		      100.00 %
>> Elapsed time:		        4.75 secs
>> Data transferred:	       37.75 MB
>> Response time:		        0.00 secs
>> Transaction rate:	     2287.79 trans/sec
>> Throughput:		        7.95 MB/sec
>> Concurrency:		        3.96
>> Successful transactions:       10867
>> Failed transactions:	           0
>> Longest transaction:	        0.01
>> Shortest transaction:	        0.00
>>
>> So, lets do it again with top running on the poor server under siege.
>> Ok, again, nice output, Mongrel2 and the 3 handlers uses all the CPU for
>> the 5s of the siege, got 2000 req/s. Everybody is happy. CPU goes back
>> to 0 after the run. Waiting a couple of minutes, getting now and then
>> connections from real clients and access the control port.
>>
>>> status tasks
>> {"task_list":[{"id": 1, "system": 0, "name": "SERVERin", "state": "read
>> wait succeeded", "extra": ""},
>> {"id": 2, "system": 0, "name": "control", "state": "read wait", "extra":
>> "running"},
>> {"id": 3, "system": 0, "name": "", "state": "", "extra": ""},
>> {"id": 4, "system": 0, "name": "Handler_task", "state": "read waitg",
>> "extra": ""},
>> {"id": 5, "system": 1, "name": "fdtask", "state": "yield", "extra":
>> "ready"},
>> {"id": 86, "system": 0, "name": "", "state": "read wait", "extra": ""},
>> {"id": 84, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 85, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 83, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 206, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 244, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 9508, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 207, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 9538, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9521, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9539, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9560, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9522, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9558, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9520, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 302, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 9526, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 299, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 300, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 301, "system": 0, "name": "HTTP", "state": "read wait", "extra": ""},
>> {"id": 9525, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9561, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9537, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9559, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9524, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9511, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9506, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9507, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9572, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9569, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9578, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9582, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9583, "system": 0, "name": "", "state": "read wait", "extra": ""},
>> {"id": 9584, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9585, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9586, "system": 0, "name": "HTTP", "state": "read wait", "extra":
>> ""},
>> {"id": 9587, "system": 0, "name": "", "state": "read wait", "extra": ""}]}
>>
>>> status net
>> {"263": {"fd": 24,"type": 1,"last_ping": 467,"last_read":
>> 467,"last_write": 467,"bytes_read": 41284,"bytes_written": 305827},
>> "184": {"fd": 26,"type": 1,"last_ping": 1663,"last_read":
>> 1658,"last_write": 1658,"bytes_read": 16938,"bytes_written": 114177},
>> "217": {"fd": 27,"type": 1,"last_ping": 1188,"last_read":
>> 1188,"last_write": 1188,"bytes_read": 12771,"bytes_written": 115544},
>> "264": {"fd": 29,"type": 1,"last_ping": 467,"last_read":
>> 467,"last_write": 467,"bytes_read": 20128,"bytes_written": 135712},
>> "185": {"fd": 30,"type": 1,"last_ping": 1663,"last_read":
>> 1663,"last_write": 1663,"bytes_read": 11378,"bytes_written": 89619},
>> "265": {"fd": 31,"type": 1,"last_ping": 467,"last_read":
>> 467,"last_write": 467,"bytes_read": 19682,"bytes_written": 129248},
>> "9480": {"fd": 32,"type": 1,"last_ping": 218,"last_read":
>> 218,"last_write": 218,"bytes_read": 18951,"bytes_written": 155429},
>> "9481": {"fd": 33,"type": 1,"last_ping": 218,"last_read":
>> 218,"last_write": 218,"bytes_read": 43559,"bytes_written": 285766},
>> "9482": {"fd": 34,"type": 1,"last_ping": 218,"last_read":
>> 218,"last_write": 218,"bytes_read": 39868,"bytes_written": 234689},
>> "70": {"fd": 35,"type": 1,"last_ping": 3078,"last_read":
>> 3078,"last_write": 3078,"bytes_read": 2257,"bytes_written": 17234},
>> "71": {"fd": 36,"type": 1,"last_ping": 3078,"last_read":
>> 3078,"last_write": 3078,"bytes_read": 5694,"bytes_written": 29838},
>> "72": {"fd": 37,"type": 1,"last_ping": 3078,"last_read":
>> 3078,"last_write": 3078,"bytes_read": 1439,"bytes_written": 18986},
>> "9472": {"fd": 38,"type": 1,"last_ping": 289,"last_read":
>> 289,"last_write": 289,"bytes_read": 26305,"bytes_written": 151256},
>> "9473": {"fd": 39,"type": 1,"last_ping": 268,"last_read":
>> 268,"last_write": 268,"bytes_read": 16355,"bytes_written": 103764},
>> "9474": {"fd": 43,"type": 1,"last_ping": 268,"last_read":
>> 268,"last_write": 263,"bytes_read": 15365,"bytes_written": 89713},
>> "9513": {"fd": 44,"type": 1,"last_ping": 21,"last_read":
>> 21,"last_write": 21,"bytes_read": 12916,"bytes_written": 91147}, "9516":
>> {"fd": 45,"type": 1,"last_ping": 21,"last_read": 21,"last_write":
>> 21,"bytes_read": 12756,"bytes_written": 81264}, "266": {"fd": 46,"type":
>> 1,"last_ping": 467,"last_read": 467,"last_write": 467,"bytes_read":
>> 10498,"bytes_written": 83696}, "9514": {"fd": 47,"type": 1,"last_ping":
>> 21,"last_read": 21,"last_write": 21,"bytes_read":
>> 433853,"bytes_written": 18185110}, "9515": {"fd": 50,"type":
>> 1,"last_ping": 21,"last_read": 21,"last_write": 21,"bytes_read":
>> 433786,"bytes_written": 10294125}, "9475": {"fd": 52,"type":
>> 1,"last_ping": 268,"last_read": 268,"last_write": 268,"bytes_read":
>> 8252,"bytes_written": 51019}, "9467": {"fd": 53,"type": 1,"last_ping":
>> 335,"last_read": 32,"last_write": 32,"bytes_read":
>> 10602,"bytes_written": 50158}, "9468": {"fd": 55,"type": 1,"last_ping":
>> 335,"last_read": 32,"last_write": 32,"bytes_read":
>> 12675,"bytes_written": 76796}, "9469": {"fd": 56,"type": 1,"last_ping":
>> 335,"last_read": 32,"last_write": 32,"bytes_read": 7808,"bytes_written":
>> 40233}, "9470": {"fd": 57,"type": 1,"last_ping": 330,"last_read":
>> 299,"last_write": 299,"bytes_read": 5024,"bytes_written": 35701},
>> "9506": {"fd": 61,"type": 1,"last_ping": 47,"last_read":
>> 47,"last_write": 47,"bytes_read": 2758,"bytes_written": 23911}, "9508":
>> {"fd": 63,"type": 1,"last_ping": 47,"last_read": 47,"last_write":
>> 47,"bytes_read": 610,"bytes_written": 18224}, "9483": {"fd": 64,"type":
>> 1,"last_ping": 208,"last_read": 208,"last_write": 203,"bytes_read":
>> 1819,"bytes_written": 16402}, "9484": {"fd": 65,"type": 1,"last_ping":
>> 203,"last_read": 203,"last_write": 203,"bytes_read":
>> 1826,"bytes_written": 16236}, "9485": {"fd": 66,"type": 1,"last_ping":
>> 203,"last_read": 203,"last_write": 203,"bytes_read":
>> 2033,"bytes_written": 12026}, "9494": {"fd": 67,"type": 1,"last_ping":
>> 135,"last_read": 135,"last_write": 135,"bytes_read":
>> 890,"bytes_written": 8201}, "9495": {"fd": 73,"type": 1,"last_ping":
>> 135,"last_read": 135,"last_write": 135,"bytes_read":
>> 1376,"bytes_written": 10785}, "9496": {"fd": 74,"type": 1,"last_ping":
>> 135,"last_read": 135,"last_write": 135,"bytes_read":
>> 411,"bytes_written": 3346}, "total": 33}
>>
>> The stay around 0, put I have these tasks without names. I am going to
>> monitor them. I wonder if the problem is triggerd when Mongrel2 reaches
>> a max of open connections waiting and tries to clean or a timeout or
>> someting like that and then the tasks without names are triggering
>> something.
>>
>> So, here I am, I am not able to reproduce the issue, but I found
>> something looking a bit strange.
>>
>> Oh, good news, while getting these 1000's of dummy internal requests,
>> the website stayed usable. So, even if the CPU was under heavy load, the
>> queue worked correctly.
>>
>> I will keep you informed.
>> loïc
>>
>> For reference:
>> $ cat mongrel2.conf
>> photon_handler = Handler(send_spec='tcp://127.0.0.1:9997',
>>                          send_ident='ac013378-26d3-4cf2-a634-757df533092d',
>>                          recv_spec='tcp://127.0.0.1:9996',
>>                          recv_ident='')
>>
>> dist_dir_handler = Dir(base='./static/',
>>                   index_file='index.html',
>>                   default_ctype='text/plain')
>>
>> main = Server(
>>     uuid="253fe638-7499-4996-a82f-d305622e8d4c",
>>     access_log="/logs/access.log",
>>     error_log="/logs/error.log",
>>     default_host="photon-project.com",
>>     chroot="./",
>>     name="baseserver",
>>     pid_file="/run/mongrel2.pid",
>>     port=80,
>>     hosts = [
>>     Host(name="photon-project.com",
>>          routes={
>>                  '/': photon_handler
>>                  }),
>>     Host(name="dist.photon-project.com",
>>          routes={
>>                  '/': dist_dir_handler
>>                  })
>>     ]
>> )
>>
>> settings = { "limits.content_length": 2097152000,
>> 	     "upload.temp_store": "/tmp/mongrel2.upload.XXXXXX" }
>> servers = [main]
> 

-- 
Dr Loïc d'Anterroches
Founder Céondo Ltd

w: www.ceondo.com       |  e: loic@ceondo.com
t: +44 (0)207 183 0016  |  f: +44 (0)207 183 0124

Céondo Ltd
Dalton House
60 Windsor Avenue
London
SW19 2RR / United Kingdom

On Sat, Feb 26, 2011 at 7:56 AM, Loic d'Anterroches <loic@ceondo.com> wrote:
> Again, sorry for the noise...
>
> Everything is explained in src/handler.c line 126. Basically, even if
> the PATH is @*, it is the handler sending the answer back to a dead
> connection which is getting the disconnect message back.

Thanks for the investigative work.  I'll be adding support for this to
the Haskell binding tonight. :)

On Sat, Feb 26, 2011 at 04:56:41PM +0100, Loic d'Anterroches wrote:
> So, now, I let my framework handle the disconnect request but if it
> failed to handle it, I pay attention to not send back an answer to Mongrel2.

Ahhh good, did you replicate that mistake from some code I wrote?  I may
be doing that too.

-- 
Zed A. Shaw
http://zedshaw.com/

Hello,

On 2011-02-26 17:16, Zed A. Shaw wrote:
> On Sat, Feb 26, 2011 at 04:56:41PM +0100, Loic d'Anterroches wrote:
>> So, now, I let my framework handle the disconnect request but if it
>> failed to handle it, I pay attention to not send back an answer to Mongrel2.
> 
> Ahhh good, did you replicate that mistake from some code I wrote?  I may
> be doing that too.

No, I did the wrong thing alone like a big boy :)
But... this is basically a system message from Mongrel2 to the handler
which is bypassing the routing set in the configuration file. I wonder
if we could had one upper case header or so to inform that this is a
system message.

At the moment this message can be reproduced by a client if you have a
@* route. Just send a jsSocket payload with disconnect. Of course it
makes nothing because the connection id cannot be spoofed, but still,
having the possibility on same cases to have a client reproduce a system
messages is not something I like.

Just thinking... I am not really sure what would be the best way to have
system communication from Mongrel2 to the handlers, but having a method
would be nice, for example, you could broadcast a "I just reload my
config, you may need to do so too" or things like that.

loïc

--
Indefero - Project management and code hosting - http://www.indefero.net
Photon - High Performance PHP Framework - http://photon-project.com
Céondo Ltd - Web + Science = Fun - http://www.ceondo.com