Background
Every week, a few of our programmers focus on responding to customer problems that might indicate a bigger issue with one of our applications. In addition, we’re constantly looking at issues (Rails exceptions, performance “hotspots”, etc.) that don’t bubble up to the customer level, but that are just “good housekeeping”. Taking care of these issues can have both real and measurable impacts — for example, we reduced application exceptions by 43% in December, allowing us to proactively fix even more problems before customers noticed.
Lets enter the house of Campfire, our real time chat product. Campfire uses memcache in a number of ways, one of which is to store fragments of messages that have been “spoken” in a room. When a user requests the transcript for that room we attempt to build a list of these messages from the cache before we hit the database. To do this, we build an array of message keys which are dispatched to a memcache-client multi_get request.
For a long time Campfire has generated exceptions showing multi_get failures, but the errors aren’t bringing down the site or causing users problems. When I first came to 37signals the exceptions were described as being caused by a bug in older versions of memcached (server), but no one knew “for sure”. Lacking any open issues or similar bug reports, as a work around our developers had patched the memcache-client to rescue ENOPIPE errors, raise by these failed get requests. The patch didn’t make the problem go away, but it kept it from being customer impacting…
Identifying the Problem
While testing a new branch of Campfire in staging, one of our developers was repeatedly encountering this error to the point where an exception was being raised for almost every page. Remember how I said these things pop up at the most inconvenient times? I decided to try and figure out these exceptions once and for all. (Ultimately, it turns out we hadn’t bundled the patched gem and that’s why the exception was being raised so often.)
After reviewing the code for memcache-client, I decided there wasn’t anything obviously wrong with its implementation for multi_get requests. To start my debugging, I fired up telnet, set two keys, and issued a “get keyone keytwo”. This worked fine. I had established that multi gets in the most basic form do work.
Next I used strace to attach to the unicorn (Ruby on Rails) process and see what the client was sending:
write(15, "get enter_messages/343555238/hide_author=false&hide_date=false&last_read=343841341 timestamp_messages/343575826/hide_author=false&hide_date=false&last_read=343841341 enter_messages/343575827/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343582929/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343582930/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343589192/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343589193/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343592436/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343592437/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343606646/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343606647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343654455/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343654456/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343663288/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663289/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663294/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663298/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663301/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663459/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663763/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663833/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343664243/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664244/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664249/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664928/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665538/hide_author=false&hide_date=true&last_read=343841341 text_messages/343665582/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665661/hide_author=false&hide_date=true&last_read=343841341 text_messages/343665730/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343668494/hide_author=false&hide_date=true&last_read=343841341 text_messages/343668495/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343670646/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343670647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343674727/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343674728/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675113/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675330/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675512/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675662/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675783/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675850/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675926/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675962/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676003/hide_author=true&hide_date=true&last_read=343841341 text_messages/343676419/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676627/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343683775/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343683778/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343697190/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343697191/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698503/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698601/hide_author=true&hide_date=true&last_read=343841341 text_messages/343698676/hi", 4096) = 4096
rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
select(17, [], [15], [], {30, 525125}) = 1 (out [15], left {30, 525122})
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(15, "de_author=false&hide_date=true&last_read=343841341 text_messages/343698734/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343699275/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699336/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699454/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699578/hide_author=false&hide_date=true&last_read=343841341 text_messages/343699907/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700196/hide_author=true&hide_date=true&last_read=343841341 text_messages/343700303/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343700490/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700491/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700960/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701033/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701249/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701495/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343701499/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701536/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701811/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343705859/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343705860/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343705927/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343707289/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707290/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707541/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707657/hide_author=false&hide_date=true&last_read=343841341 text_messages/343708101/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343711297/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343711298/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343711359/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343714551/hide_author=false&hide_date=true&last_read=343841341 text_messages/343714552/hide_author=false&hide_date=true&last_read=343841341 text_messages/343714779/hide_author=false&hide_date=true&last_read=343841341 text_messages/343715190/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715303/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715380/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715452/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715558/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716023/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716257/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716298/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716338/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716577/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716745/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716816/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716900/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716999/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343717255/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717256/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717265/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717555/hide_author=true&hide_date=true&last_read=343841341 text_messages/343717960/hide_author=true&hide_date=true&last_read=343841341 text_messages/343718088/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718097/hide_author=false&hide_date=true&last_read=343841341 text_messages/34371819", 4096) = 4096
--- SIGRT_27 (Real-time signal 25) @ 0 (0) ---
getrusage(RUSAGE_SELF, {ru_utime={4, 270000}, ru_stime={0, 190000}, ...}) = 0
timer_settime(0x14, 0, {it_interval={0, 12712000}, it_value={0, 12712000}}, NULL) = 0
rt_sigreturn(0x4b5412a22c0ef) = 4096
rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
select(17, [], [15], [], {30, 517198}) = 1 (out [15], left {30, 517196})
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(15, "2/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718248/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718670/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718779/hide_author=true&hide_date=true&last_read=343841341 text_messages/343718955/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343725746/hide_author=false&hide_date=true&last_read=343841341 text_messages/343725747/hide_author=false&hide_date=true&last_read=343841341 text_messages/343725757/hide_author=true&hide_date=true&last_read=343841341 text_messages/343725762/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343729823/hide_author=false&hide_date=true&last_read=343841341 text_messages/343729824/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343758537/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343758538/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343764428/hide_author=false&hide_date=true&last_read=343841341 text_messages/343764429/hide_author=false&hide_date=true&last_read=343841341 text_messages/343764474/hide_author=true&hide_date=true&last_read=343841341 text_messages/343764528/hide_author=true&hide_date=true&last_read=343841341 text_messages/343764620/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343773529/hide_author=false&hide_date=true&last_read=343841341 text_messages/343773530/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343783468/hide_author=false&hide_date=true&last_read=343841341 text_messages/343783469/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343783615/hide_author=true&hide_date=true&last_read=343841341 text_messages/343783650/hide_author=true&hide_date=true&last_read=343841341 text_messages/343783875/hide_author=true&hide_date=true&last_read=343841341 text_messages/343784004/hide_author=true&hide_date=true&last_read=343841341 text_messages/343784277/hide_author=false&hide_date=true&last_read=343841341 text_messages/343784372/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343784578/hide_author=false&hide_date=true&last_read=343841341 text_messages/343784579/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343802940/hide_author=false&hide_date=true&last_read=343841341 text_messages/343802941/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343802954/hide_author=true&hide_date=true&last_read=343841341 text_messages/343803300/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343812622/hide_author=false&hide_date=true&last_read=343841341 text_messages/343812623/hide_author=false&hide_date=true&last_read=343841341 text_messages/343813469/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343813500/hide_author=true&hide_date=true&last_read=343841341 text_messages/343813695/hide_author=true&hide_date=true&last_read=343841341 text_messages/343813765/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814066/hide_author=true&hide_date=true&last_read=343841341 enter_messages/343814107/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343814360/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814556/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343814680/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814681/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815559/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815889/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343815893/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815915/hide_author=true&hide_date=true&last_read=343841341 text_messages/343815953/hide_author=true&hide_date=true&last_read=343841341 text_messages/343816359/hide_author=false&hide_date=true&last_read=343841341 text_messages/343816657/hide_author=true&hide_date=true&last_read=3438413", 4096) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
sendto(9, "<13>Dec 29 20:43:11 campfire[17363]: [37s] Generic failure: Errno::EPIPE: Broken pipe", 85, MSG_NOSIGNAL, NULL, 0) = 85
rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
select(17, [], [15], [], {30, 516190}) = 1 (out [15], left {30, 516188})
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
select(17, [], [15], [], {30, 516071}) = 1 (out [15], left {30, 516069})
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(15, "get enter_messages/343555238/hide_author=false&hide_date=false&last_read=343841341 timestamp_messages/343575826/hide_author=false&hide_date=false&last_read=343841341 enter_messages/343575827/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343582929/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343582930/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343589192/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343589193/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343592436/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343592437/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343606646/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343606647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343654455/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343654456/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343663288/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663289/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663294/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663298/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663301/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663459/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663763/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663833/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343664243/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664244/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664249/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664928/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665538/hide_author=false&hide_date=true&last_read=343841341 text_messages/343665582/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665661/hide_author=false&hide_date=true&last_read=343841341 text_messages/343665730/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343668494/hide_author=false&hide_date=true&last_read=343841341 text_messages/343668495/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343670646/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343670647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343674727/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343674728/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675113/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675330/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675512/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675662/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675783/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675850/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675926/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675962/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676003/hide_author=true&hide_date=true&last_read=343841341 text_messages/343676419/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676627/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343683775/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343683778/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343697190/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343697191/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698503/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698601/hide_author=true&hide_date=true&last_read=343841341 text_messages/343698676/hi", 4096) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
sendto(9, "<13>Dec 29 20:43:11 campfire[17363]: [37s] Generic failure: Errno::EPIPE: Broken pipe", 85, MSG_NOSIGNAL, NULL, 0) = 85
close(15) = 0
munmap(0x7f7114948000, 4096) = 0
close(15) = -1 EBADF (Bad file descriptor)
Here’s a basic run down of what you see above: The unicorn process (Rails) opens a socket to our memcache server in staging, and then issues a get command which is broken up into multiple 4096 byte packets. However, instead of receiving a reply from the server, our client socket gets a Broken Pipe error and it’s closed.
“OK…” I thought. I need to reference the memcache protocol specification and make sure this request conforms to the “get” protocol command. Was this request within in the protocol description? Yes.
At this point I knew the client was sending a legitimate request, so I needed to debug the server. Since our application uses multiple instances, I downed all but one instance, and fired up strace (strace -s 64000 -fp 7133).
[pid 7136] epoll_wait(19, {{EPOLLIN, {u32=32, u64=32}}}, 32, 4294967295) = 1
[pid 7136] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7136] read(32, "get enter_messages/343555238/hide_author=false&hide_date=false&last_read=343841341 timestamp_messages/343575826/hide_author=false&hide_date=false&last_read=343841341 enter_messages/343575827/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343582929/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343582930/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343589192/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343589193/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343592436/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343592437/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343606646/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343606647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343654455/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343654456/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343663288/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663289/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663294/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663298/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663301/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663459/hide_author=false&hide_date=true&last_read=343841341 text_messages/343663763/hide_author=true&hide_date=true&last_read=343841341 text_messages/343663833/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343664243/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664244/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664249/hide_author=false&hide_date=true&last_read=343841341 text_messages/343664928/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665538/hide_author=false&hide_date=true&last_read=343841341", 2048) = 2048
[pid 7136] read(32, " text_messages/343665582/hide_author=true&hide_date=true&last_read=343841341 text_messages/343665661/hide_author=false&hide_date=true&last_read=343841341 text_messages/343665730/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343668494/hide_author=false&hide_date=true&last_read=343841341 text_messages/343668495/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343670646/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343670647/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343674727/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343674728/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675113/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675330/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675512/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675662/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675783/hide_author=true&hide_date=true&last_read=343841341 text_messages/343675850/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675926/hide_author=false&hide_date=true&last_read=343841341 text_messages/343675962/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676003/hide_author=true&hide_date=true&last_read=343841341 text_messages/343676419/hide_author=false&hide_date=true&last_read=343841341 text_messages/343676627/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343683775/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343683778/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343697190/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343697191/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698503/hide_author=false&hide_date=true&last_read=343841341 text_messages/343698601/hide_author=true&hide_date=true&last_read=343841341 text_messages/343698676/hi", 2048) = 2048
[pid 7136] read(32, "de_author=false&hide_date=true&last_read=343841341 text_messages/343698734/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343699275/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699336/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699454/hide_author=true&hide_date=true&last_read=343841341 text_messages/343699578/hide_author=false&hide_date=true&last_read=343841341 text_messages/343699907/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700196/hide_author=true&hide_date=true&last_read=343841341 text_messages/343700303/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343700490/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700491/hide_author=false&hide_date=true&last_read=343841341 text_messages/343700960/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701033/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701249/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701495/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343701499/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701536/hide_author=true&hide_date=true&last_read=343841341 text_messages/343701811/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343705859/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343705860/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343705927/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343707289/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707290/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707541/hide_author=false&hide_date=true&last_read=343841341 text_messages/343707657/hide_author=false&hide_date=true&last_read=343841341 text_messages/343708101/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343711297/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343711298/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343711359/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343714551/hide_author=false&hide_date=true&last_read=343841341 text_messages/343714552/hide_author=false&hide_date=true&last_read=343841341 text_messages/343714779/hide_author=false&hide_date=true&last_read=343841341 text_messages/343715190/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715303/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715380/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715452/hide_author=true&hide_date=true&last_read=343841341 text_messages/343715558/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716023/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716257/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716298/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716338/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716577/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716745/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716816/hide_author=true&hide_date=true&last_read=343841341 text_messages/343716900/hide_author=false&hide_date=true&last_read=343841341 text_messages/343716999/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343717255/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717256/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717265/hide_author=false&hide_date=true&last_read=343841341 text_messages/343717555/hide_author=true&hide_date=true&last_read=343841341 text_messages/343717960/hide_author=true&hide_date=true&last_read=343841341 text_messages/343718088/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718097/hide_author=false&hide_date=true&last_read=343841341 text_messages/34371819", 4096) = 4096
[pid 7136] rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
[pid 7136] read(32, "2/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718248/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718670/hide_author=false&hide_date=true&last_read=343841341 text_messages/343718779/hide_author=true&hide_date=true&last_read=343841341 text_messages/343718955/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343725746/hide_author=false&hide_date=true&last_read=343841341 text_messages/343725747/hide_author=false&hide_date=true&last_read=343841341 text_messages/343725757/hide_author=true&hide_date=true&last_read=343841341 text_messages/343725762/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343729823/hide_author=false&hide_date=true&last_read=343841341 text_messages/343729824/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343758537/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343758538/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343764428/hide_author=false&hide_date=true&last_read=343841341 text_messages/343764429/hide_author=false&hide_date=true&last_read=343841341 text_messages/343764474/hide_author=true&hide_date=true&last_read=343841341 text_messages/343764528/hide_author=true&hide_date=true&last_read=343841341 text_messages/343764620/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343773529/hide_author=false&hide_date=true&last_read=343841341 text_messages/343773530/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343783468/hide_author=false&hide_date=true&last_read=343841341 text_messages/343783469/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343783615/hide_author=true&hide_date=true&last_read=343841341 text_messages/343783650/hide_author=true&hide_date=true&last_read=343841341 text_messages/343783875/hide_author=true&hide_date=true&last_read=343841341 text_messages/343784004/hide_author=true&hide_date=true&last_read=343841341 text_messages/343784277/hide_author=false&hide_date=true&last_read=343841341 text_messages/343784372/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343784578/hide_author=false&hide_date=true&last_read=343841341 text_messages/343784579/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343802940/hide_author=false&hide_date=true&last_read=343841341 text_messages/343802941/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343802954/hide_author=true&hide_date=true&last_read=343841341 text_messages/343803300/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343812622/hide_author=false&hide_date=true&last_read=343841341 text_messages/343812623/hide_author=false&hide_date=true&last_read=343841341 text_messages/343813469/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343813500/hide_author=true&hide_date=true&last_read=343841341 text_messages/343813695/hide_author=true&hide_date=true&last_read=343841341 text_messages/343813765/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814066/hide_author=true&hide_date=true&last_read=343841341 enter_messages/343814107/hide_author=false&hide_date=true&last_read=343841341 upload_messages/343814360/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814556/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343814680/hide_author=false&hide_date=true&last_read=343841341 text_messages/343814681/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815559/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815889/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343815893/hide_author=false&hide_date=true&last_read=343841341 text_messages/343815915/hide_author=true&hide_date=true&last_read=343841341 text_messages/343815953/hide_author=true&hide_date=true&last_read=343841341 text_messages/343816359/hide_author=false&hide_date=true&last_read=343841341 text_messages/343816657/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343816830/hide_author=false&hide_date=true&last_read=343841341 text_messages/343817036/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343817042/hide_author=true&hide_date=true&last_read=343841341 text_messages/343817189/hide_author=false&hide_date=true&last_read=343841341 text_messages/343817229/hide_author=true&hide_date=true&last_read=343841341 text_messages/343817955/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343818321/hide_author=false&hide_date=true&last_read=343841341 text_messages/343818322/hide_author=false&hide_date=true&last_read=343841341 text_messages/343819079/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343825796/hide_author=false&hide_date=true&last_read=343841341 text_messages/343825797/hide_author=false&hide_date=true&last_read=343841341 text_messages/343825802/hide_author=true&hide_date=true&last_read=343841341 text_messages/343825809/hide_author=true&hide_date=true&last_read=343841341 text_messages/343826383/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343826403/hide_author=true&hide_date=true&last_read=343841341 text_messages/343826708/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343826722/hide_author=true&hide_date=true&last_read=343841341 text_messages/343827244/hide_author=true&hide_date=true&last_read=343841341 text_messages/343827298/hide_author=true&hide_date=true&last_read=343841341 text_messages/343827299/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343830049/hide_author=false&hide_date=true&last_read=343841341 text_messages/343830050/hide_author=false&hide_date=true&last_read=343841341 text_messages/343830187/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343831000/hide_author=false&hide_date=true&last_read=343841341 text_messages/343831001/hide_author=false&hide_date=true&last_read=343841341 text_messages/343831123/hide_author=true&hide_date=true&last_read=343841341 text_messages/343831211/hide_author=true&hide_date=true&last_read=343841341 text_messages/343831487/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343831492/hide_author=true&hide_date=true&last_read=343841341 text_messages/343831675/hide_author=false&hide_date=true&last_read=343841341 text_messages/343831725/hide_author=true&hide_date=true&last_read=343841341 text_messages/343831788/hide_author=true&hide_date=true&last_read=343841341 text_messages/343831979/hide_author=false&hide_date=true&last_read=343841341 text_messages/343833552/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343834848/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343834849/hide_author=false&hide_date=true&last_read=343841341 text_messages/343834896/hide_author=true&hide_date=true&last_read=343841341 text_messages/343835031/hide_author=false&hide_date=true&last_read=343841341 text_messages/343836063/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343840446/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343840447/hide_author=false&hide_date=true&last_read=343841341 text_messages/343840829/hide_author=false&hide_date=true&last_read=343841341 text_messages/343840885/hide_author=false&hide_date=true&last_read=343841341 text_messages/343841050/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343841076/hide_author=true&hide_date=true&last_read=343841341 text_messages/343841236/hide_author=false&hide_date=true&last_read=343841341 text_messages/343841341/hide_author=true&hide_date=true&last_read=343841341 text_messages/343841351/hide_author=false&hide_date=true&last_read=343841341 text_messages/343841428/hide_author=true&hide_date=true&last_read=343841341 text_messages/343841582/hide_author=true&hide_date=true&last_read=343841341 text_messages/343841603/hide_author=false&hide_date=true&last_read=343841341 text_messages/343841692/hide_author=true&hide_date=true&last_read=343841341 text_messages/343841855/hide_author=true&hide_date=true&last_read=343841341", 8192) = 8192
[pid 7136] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7136] rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
[pid 7136] read(32, " text_messages/343841924/hide_author=false&hide_date=true&last_read=343841341 text_messages/343841969/hide_author=false&hide_date=true&last_read=343841341 text_messages/343842042/hide_author=false&hide_date=true&last_read=343841341 text_messages/343842523/hide_author=true&hide_date=true&last_read=343841341 text_messages/343842910/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843039/hide_author=true&hide_date=true&last_read=343841341 text_messages/343843171/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843284/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343843427/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843428/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343843476/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843477/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843547/hide_author=false&hide_date=true&last_read=343841341 text_messages/343843686/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343843878/hide_author=true&hide_date=true&last_read=343841341 text_messages/343843929/hide_author=false&hide_date=true&last_read=343841341 text_messages/343844070/hide_author=false&hide_date=true&last_read=343841341 text_messages/343844547/hide_author=false&hide_date=true&last_read=343841341 text_messages/343844842/hide_author=true&hide_date=true&last_read=343841341 text_messages/343844983/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343847757/hide_author=false&hide_date=true&last_read=343841341 text_messages/343847758/hide_author=false&hide_date=true&last_read=343841341 text_messages/343848887/hide_author=true&hide_date=true&last_read=343841341 text_messages/343849266/hide_author=false&hide_date=true&last_read=343841341 text_messages/343849330/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343850692/hide_author=false&hide_date=true&last_read=343841341 text_messages/343850693/hide_author=false&hide_date=true&last_read=343841341 text_messages/343850994/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343851014/hide_author=true&hide_date=true&last_read=343841341 text_messages/343851040/hide_author=false&hide_date=true&last_read=343841341 text_messages/343851100/hide_author=true&hide_date=true&last_read=343841341 text_messages/343851171/hide_author=false&hide_date=true&last_read=343841341 text_messages/343852048/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343852052/hide_author=true&hide_date=true&last_read=343841341 text_messages/343852107/hide_author=true&hide_date=true&last_read=343841341 text_messages/343852129/hide_author=true&hide_date=true&last_read=343841341 text_messages/343852168/hide_author=true&hide_date=true&last_read=343841341 text_messages/343852282/hide_author=false&hide_date=true&last_read=343841341 text_messages/343852487/hide_author=false&hide_date=true&last_read=343841341 text_messages/343852631/hide_author=true&hide_date=true&last_read=343841341 text_messages/343852765/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343855843/hide_author=false&hide_date=true&last_read=343841341 text_messages/343855844/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343856603/hide_author=false&hide_date=true&last_read=343841341 text_messages/343856604/hide_author=false&hide_date=true&last_read=343841341 text_messages/343856802/hide_author=false&hide_date=true&last_read=343841341 text_messages/343856970/hide_author=false&hide_date=true&last_read=343841341 text_messages/343857838/hide_author=false&hide_date=true&last_read=343841341 text_messages/343858343/hide_author=false&hide_date=true&last_read=343841341 text_messages/343858380/hide_author=false&hide_date=true&last_read=343841341 text_messages/343858474/hide_author=true&hide_date=true&last_read=343841341 text_messages/343858544/hide_author=true&hide_date=true&last_read=343841341 text_messages/343858596/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343863819/hide_author=false&hide_date=true&last_read=343841341 text_messages/343863820/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343863844/hide_author=true&hide_date=true&last_read=343841341 text_messages/343864027/hide_author=true&hide_date=true&last_read=343841341 text_messages/343864037/hide_author=false&hide_date=true&last_read=343841341 text_messages/343864071/hide_author=false&hide_date=true&last_read=343841341 text_messages/343864588/hide_author=false&hide_date=true&last_read=343841341 text_messages/343864630/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343864755/hide_author=false&hide_date=true&last_read=343841341 text_messages/343865034/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343866397/hide_author=false&hide_date=true&last_read=343841341 text_messages/343866398/hide_author=false&hide_date=true&last_read=343841341 text_messages/343866591/hide_author=true&hide_date=true&last_read=343841341 paste_messages/343866596/hide_author=true&hide_date=true&last_read=343841341 text_messages/343867002/hide_author=true&hide_date=true&last_read=343841341 text_messages/343867646/hide_author=false&hide_date=true&last_read=343841341 text_messages/343868189/hide_author=false&hide_date=true&last_read=343841341 text_messages/343868443/hide_author=false&hide_date=true&last_read=343841341 text_messages/343868603/hide_author=false&hide_date=true&last_read=343841341 text_messages/343868688/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343868946/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343868947/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343869494/hide_author=false&hide_date=true&last_read=343841341 text_messages/343869517/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343875073/hide_author=false&hide_date=true&last_read=343841341 text_messages/343875074/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343875398/hide_author=true&hide_date=true&last_read=343841341 text_messages/343875689/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343877689/hide_author=false&hide_date=true&last_read=343841341 text_messages/343877690/hide_author=false&hide_date=true&last_read=343841341 text_messages/343878129/hide_author=false&hide_date=true&last_read=343841341 text_messages/343878477/hide_author=false&hide_date=true&last_read=343841341 text_messages/343878485/hide_author=true&hide_date=true&last_read=343841341 text_messages/343878491/hide_author=true&hide_date=true&last_read=343841341 text_messages/343878499/hide_author=false&hide_date=true&last_read=343841341 text_messages/343878588/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343880810/hide_author=false&hide_date=true&last_read=343841341 text_messages/343880811/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343880830/hide_author=true&hide_date=true&last_read=343841341 text_messages/343880919/hide_author=false&hide_date=true&last_read=343841341 text_messages/343880994/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343885259/hide_author=false&hide_date=true&last_read=343841341 text_messages/343885260/hide_author=false&hide_date=true&last_read=343841341 text_messages/343885374/hide_author=true&hide_date=true&last_read=343841341 text_messages/343885436/hide_author=true&hide_date=true&last_read=343841341 text_messages/343885452/hide_author=true&hide_date=true&last_read=343841341 enter_messages/343885679/hide_author=false&hide_date=true&last_read=343841341 text_messages/343885711/hide_author=false&hide_date=true&last_read=343841341 text_messages/343885723/hide_author=true&hide_date=true&last_read=343841341 text_messages/343885744/hide_author=true&hide_date=true&last_read=343841341 text_messages/343885878/hide_author=true&hide_date=true&last_read=343841341 text_messages/343886065/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343886343/hide_author=false&hide_date=true&last_read=343841341 text_messages/343886344/hide_author=false&hide_date=true&last_read=343841341 text_messages/343888444/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343890769/hide_author=false&hide_date=true&last_read=343841341 text_messages/343890770/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343894891/hide_author=false&hide_date=true&last_read=343841341 text_messages/343894892/hide_author=false&hide_date=true&last_read=343841341 text_messages/343895056/hide_author=false&hide_date=true&last_read=343841341 text_messages/343895130/hide_author=true&hide_date=true&last_read=343841341 text_messages/343895152/hide_author=true&hide_date=true&last_read=343841341 text_messages/343895269/hide_author=true&hide_date=true&last_read=343841341 text_messages/343895393/hide_author=true&hide_date=true&last_read=343841341 text_messages/343895542/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343902958/hide_author=false&hide_date=true&last_read=343841341 text_messages/343902959/hide_author=false&hide_date=true&last_read=343841341 text_messages/343903053/hide_author=true&hide_date=true&last_read=343841341 text_messages/343903267/hide_author=false&hide_date=true&last_read=343841341 text_messages/343903512/hide_author=false&hide_date=true&last_read=343841341 text_messages/343903628/hide_author=false&hide_date=true&last_read=343841341 text_messages/343903725/hide_author=true&hide_date=true&last_read=343841341 text_messages/343903864/hide_author=true&hide_date=true&last_read=343841341 text_messages/343903882/hide_author=false&hide_date=true&last_read=343841341 text_messages/343903968/hide_author=false&hide_date=true&last_read=343841341 text_messages/343904055/hide_author=false&hide_date=true&last_read=343841341 text_messages/343904090/hide_author=true&hide_date=true&last_read=343841341 text_messages/343904553/hide_author=false&hide_date=true&last_read=343841341 text_messages/343904624/hide_author=true&hide_date=true&last_read=343841341 text_messages/343904678/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343908400/hide_author=false&hide_date=true&last_read=343841341 text_messages/343908401/hide_author=false&hide_date=true&last_read=343841341 text_messages/343908458/hide_author=false&hide_date=true&last_read=343841341 text_messages/343908510/hide_author=false&hide_date=true&last_read=343841341 text_messages/343908566/hide_author=true&hide_date=true&last_read=343841341 text_messages/343908629/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343910155/hide_author=false&hide_date=true&last_read=343841341 text_messages/343910156/hide_author=false&hide_date=true&last_read=343841341 text_messages/343910180/hide_author=true&hide_date=true&last_read=343841341 text_messages/343910261/hide_author=true&hide_date=true&last_read=343841341 text_messages/343910355/hide_author=true&hide_date=true&last_read=343841341 text_messages/343910536/hide_author=true&hide_date=true&last_read=343841341 text_messages/343910565/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343912945/hide_author=false&hide_date=true&last_read=343841341 text_messages/343912946/hide_author=false&hide_date=true&last_read=343841341 text_messages/343912955/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343917638/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343917639/hide_author=false&hide_date=true&last_read=343841341 text_messages/343919040/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343928070/hide_author=false&hide_date=true&last_read=343841341 text_messages/343928071/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343944056/hide_author=false&hide_date=true&last_read=343841341 text_messages/343944057/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343946376/hide_author=false&hide_date=true&last_read=343841341 text_messages/343946377/hide_author=false&hide_date=true&last_read=343841341 text_messages/343946786/hide_author=true&hide_date=true&last_read=343841341 text_messages/343947443/hide_author=true&hide_date=true&last_read=343841341 text_messages/343948263/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343951411/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343951412/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343958275/hide_author=false&hide_date=true&last_read=343841341 text_messages/343958276/hide_author=false&hide_date=true&last_read=343841341 paste_messages/343958310/hide_author=true&hide_date=true&last_read=343841341 text_messages/343959039/hide_author=false&hide_date=true&last_read=343841341 text_messages/343959484/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/343961703/hide_author=false&hide_date=true&last_read=343841341 text_messages/343961704/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343972558/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343972559/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343976120/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343976121/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343982780/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343982781/hide_author=false&hide_date=true&last_read=343841341 text_messages/343982834/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343984059/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343984060/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343987418/hide_author=false&hide_date=true&last_read=343841341 enter_messages/343987419/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/343997513/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343997514/hide_author=false&hide_date=true&last_read=343841341 kick_messages/343997666/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/344008833/hide_author=false&hide_date=true&last_read=343841341 enter_messages/344008834/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/344009870/hide_author=false&hide_date=true&last_read=343841341 text_messages/344009871/hide_author=false&hide_date=true&last_read=343841341 text_messages/344010043/hide_author=false&hide_date=true&last_read=343841341 upload_messages/344010066/hide_author=true&hide_date=true&last_read=343841341 upload_messages/344010083/hide_author=true&hide_date=true&last_read=343841341 text_messages/344010323/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/344015438/hide_author=false&hide_date=true&last_read=343841341 kick_messages/344015439/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/344018437/hide_author=false&hide_date=true&last_read=343841341 kick_messages/344018438/hide_author=false&hide_date=true&last_read=343841341 timestamp_messages/344033626/hide_author=false&hide_date=true&last_read=343841341 enter_messages/344033627/hide_author=false&hide_date=true&last_read=343841341 text_messages/344033767/hide_author=false&hide_date=true&last_read=343841341 text_messages/344033769/hide_author=true&hide_date=true&last_read=343841341 text_messages/344033772/hide_author=true&hide_date=true&last_read=343841341 text_messages/344033774/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/344041143/hide_author=false&hide_date=true&last_read=343841341 upload_messages/344041144/hide_author=false&hide_date=true&last_read=343841341 text_messages/344041191/hide_author=true&hide_date=true&last_read=343841341 text_messages/344041227/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/344041414/hide_author=false&hide_date=true&last_read=343841341 text_messages/344041415/hide_author=false&hide_date=true&last_read=343841341 text_messages/344041637/hide_author=true&hide_date=true&last_read=343841341 text_messages/344041654/hide_author=true&hide_date=true&last_read=343841341 timestamp_messages/344052470/hide_author=false&hide_date=true", 16384) = 16384
[pid 7136] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7136] --- SIGRT_27 (Real-time signal 25) @ 0 (0) ---
[pid 7136] getrusage(RUSAGE_SELF, {ru_utime={12, 90000}, ru_stime={13, 600000}, ...}) = 0
[pid 7136] rt_sigreturn(0x4b54187fd1996) = 0
[pid 7136] epoll_ctl(19, EPOLL_CTL_DEL, 32, {EPOLLIN, {u32=32, u64=32}}) = 0
[pid 7136] close(32) = 0
[pid 7136] listen(28, 1024) = 0
[pid 7136] listen(27, 1024) = 0
[pid 7136] brk(0) = 0x1c52000
[pid 7136] brk(0) = 0x1c52000
[pid 7136] brk(0) = 0x1c52000
[pid 7136] brk(0x1c4b000) = 0x1c4b000
[pid 7136] brk(0) = 0x1c4b000
[pid 7136] brk(0) = 0x1c4b000
[pid 7136] brk(0) = 0x1c4b000
[pid 7136] brk(0) = 0x1c4b000
[pid 7136] brk(0x1c49000) = 0x1c49000
[pid 7136] brk(0) = 0x1c49000
[pid 7136] rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
[pid 7136] epoll_wait(19, <unfinished ...>
[pid 7133] <... epoll_wait resumed> {}, 32, 85) = 0
[pid 7133] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7133] --- SIGRT_27 (Real-time signal 25) @ 0 (0) ---
[pid 7133] getrusage(RUSAGE_SELF, {ru_utime={12, 90000}, ru_stime={13, 600000}, ...}) = 0
[pid 7133] timer_settime(0x104, 0, {it_interval={0, 12812000}, it_value={0, 12812000}}, NULL) = 0
[pid 7133] rt_sigreturn(0x4b54187fe0371) = 0
[pid 7133] rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
[pid 7133] epoll_wait(3, {}, 32, 1) = 0
[pid 7133] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7133] rt_sigprocmask(SIG_BLOCK, [RT_27 RT_28], [], 8) = 0
[pid 7133] epoll_wait(3, {}, 32, 1000) = 0
[pid 7133] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 7133] --- SIGRT_27 (Real-time signal 25) @ 0 (0) ---
[pid 7133] getrusage(RUSAGE_SELF, {ru_utime={12, 90000}, ru_stime={13, 600000}, ...}) = 0
[pid 7133] timer_settime(0x104, 0, {it_interval={0, 12787000}, it_value={0, 12787000}}, NULL) = 0
[pid 7133] rt_sigreturn(0x4b541880d6c8e) = 0
(Strace Tip: I used -f to follow the forked processes, and -s 64000 to make sure I got enough string output to see the full read/write data sent to the socket.)
You can see that the memcache server reads the first 2048 bytes, then reads another 2048 bytes, then reads another 4096 bytes, then reads 8192 bytes, and finally reads another 16384 bytes. So after the first read, it doubles the amount of data it’s reading for each iteration. However, after the fourth read, the epoll call returns 0, and the client’s connection is closed.
Identifying the Root Cause
In this case, I knew Jeremy had worked on this bug before and I thought he would understand the all the data I had gathered. So with Jeremy’s help, I started looking at the memcache code on Github. Within minutes Jeremy pinged me saying he had noticed this code that’s designed to nuke junk connections. Which makes sense, but also doesn’t help us here!
This code path does exactly what I had seen in the strace above: It reads from buffer 4 times, while doubling the amount read each time. After 4 times, it stops reading and returns.
Conclusion and Resolution
Although memcache’s behavior is by design, it’s not compatible with the expected behavior of the protocol. In the issue I opened, I recommended a configuration option to set the amount of data to read, or the number of times to attempt reading more data. I’m not sure if this is a realistic solution though.
Hypothetically we could work around this by increasing the initial buffer size and recompiling memcache so that in 4 iterations the server would receive all of the get command. We could also patch the memcache-client multi_get method to break the multi_get requests into multiple requests with fewer keys. For now we’ve left our patched client in place, with hope that the memcache team will be able to get this resolved soon.
As I said previously, the goal is to identify a root cause. And, with Jeremy’s help, I’ve done just that. It feels great to have a complete understanding of this exception, and where the break down is in our stack.
We now know, we don’t have to be afraid of upgrading memcache with a fear of causing more multi_get problems. We also know that this is a legitimate problem that’s causing a significant performance penalty in our application. (Since large multi_gets fail, that means we aren’t getting the data back from memcache and hitting the database more than we need to.) Finally, for me, it shows that I don’t have to be bothered by debugging with strace. I’m no C code expert, but even with my limited understanding, strace provided enough clues for me to follow this all the way to the source in less than one hour. And since you all have an extra hour to spare, I hope this encourages you to take a look at that problem that’s been lingering in your stack.
Michael
on 04 Jan 12Thanks. I learned a LOT from this.
Dmitry Nikolaev
on 04 Jan 12I think the problem is to find good balance between what to do and how to do. Yes, it is good to respond to every exception. It is better to remove all bugs. But, as many times, the really big question is about how to balance between all stuff around you. It’s not secret for most of us that exceptions are bad.
Swami Atma
on 04 Jan 12Excellent post. Very informative and useful.
Please do work on your its and it’s. These mistakes are reflecting poorly on you and 37signals.
Taylor
on 04 Jan 12@Dmitry,
I agree. We tend to get lots of exceptions for the same thing, but on different accounts. We’ve found a daily digest email showing a count of similar exceptions works well.
@Swami,
Thanks for the feed back! I believe the grammar errors have been corrected.
Eric
on 04 Jan 12Would it not take just a few minutes to comment out the junk check and test? Still seems like you are beating up on memcached with these long multigets.
Anonymous Coward
on 04 Jan 12TL;DR; – 37signals has memcache segfault and still doesn’t know why (root cause)
Will Jessop
on 04 Jan 12Just to avoid any confusion, memcached didn’t segfault and we found the root cause.
Jordan
on 05 Jan 12Interesting post. It reminded me the old days when I was a sysadmin and we had memcached problems too. strace on php, so funny. :-)
Paul W
on 05 Jan 12I regularly use strace to try and debug problems (particularly with the “-f” flag) – but sometimes the output of strace is so verbose it’s almost impossible to see the wood for the trees…
In your example, I like the way you break the strace output down into piece by piece chunks to try and zero in on the issue.
Watched an interesting talk recently on data trawling (log data, as opposed to strace) that drilled down on problems in an interesting “low tech” way and eventually resolved the issue. Can be seen here: Velocity 2011 conference. Most interesting bit (for me) was from 13 mins in….
Very useful post. Thanks for this.
Cheers
Taylor
on 05 Jan 12@Paul W,
Thanks for sharing that velocity video. I once printed 20 pages of Perl script to annotate by hand, for conversion to PHP. Worked remarkably well!
Regarding strace options, I often use -etrace=read,write if I want to narrow down my trace to reads and writes only (for example). I also frequently use -o to write the output to a file so I can use awk / sed / grep to find the parts I’m really interested in. I also frequently combine the strace output with lsof -f output so I know the fd -> open file / socket mapping.
ploogman
on 05 Jan 12excellent post – thank you -
Allan Ebdrup
on 05 Jan 12Weeding out in the exceptions you log is great practise. All to often I’ve seen logs that have become too cluttered and have lost a lot of their value, because they just fill up. Good on you for being proactive about this.
But let me ask you this? What about JavaScript errors? I’ve come across several JavaScript errors in basecamp, and every time I wonder, are they logging these?
GrammarPolice
on 07 Jan 12Really annoying that someone has to comment about apostrophe’s in posts. I wonder if he complains to people that text him “ur” instead of “you’re” as well.
Swami, get over it. Clown.
Thanks for the post !
Skill-guru
on 10 Jan 12yes you cannot ignore exceptions unless you never know when they bring your application down. has this issue with memcache been reported to them and fixed?
This discussion is closed.