Note that there are some explanatory texts on larger screens.

plurals
  1. POThin server process hanging at 100% CPU in what appears to be a regex loop. Where can I get more information to debug?
    primarykey
    data
    text
    <p>I have a gdb backtrace on it that yields this:</p> <pre><code>#0 match_at (reg=0xcce4a00, str=0xd47b101 "206193045.1297252703.66.40.utmcsr=sendmail|utmccn=52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off", end=0xd47b1a6 "", sstart=0xd47b101 "206193045.1297252703.66.40.utmcsr=sendmail|utmccn=52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off", sprev=0xd47b131 "52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off", msa=0x7fff7bc66870) at regexec.c:2433 #1 0x00002b785390329c in onig_search (reg=0xcce4a00, str=0xd47b101 "206193045.1297252703.66.40.utmcsr=sendmail|utmccn=52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off", end=0xd47b1a6 "", start=&lt;value optimized out&gt;, range=0xd47b102 "06193045.1297252703.66.40.utmcsr=sendmail|utmccn=52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off", region=0x7fff7bc66990, option=0) at regexec.c:3646 #2 0x00002b78538ef51e in rb_reg_search (re=137570880, str=218457520, pos=0, reverse=0) at re.c:1372 #3 0x00002b78538efc42 in rb_reg_match (re=214846549, str=218457520) at re.c:2740 #4 0x00002b7853971c36 in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:2089 #5 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #6 0x00002b7853970cd9 in invoke_block_from_c (th=0x8329020, block=0x2b78572fea38, self=174397400, argc=1, argv=0x0, blockptr=0x0, cref=0x0) at vm.c:558 #7 0x00002b785397b037 in vm_yield (val=218457520) at vm.c:588 #8 rb_yield_0 (val=218457520) at vm_eval.c:740 #9 rb_yield (val=218457520) at vm_eval.c:750 #10 0x00002b7853840926 in rb_ary_collect (ary=218457680) at array.c:2166 #11 0x00002b78539716aa in vm_call_cfunc (th=0x8329020, cfp=0x2b78572fea10, num=0, blockptr=0x2b78572fea39, flag=0, id=1544, me=0x83e0ac0, recv=218457680) at vm_insnhelper.c:402 #12 vm_call_method (th=0x8329020, cfp=0x2b78572fea10, num=0, blockptr=0x2b78572fea39, flag=0, id=1544, me=0x83e0ac0, recv=218457680) at vm_insnhelper.c:524 #13 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #14 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #15 0x00002b7853970cd9 in invoke_block_from_c (th=0x8329020, block=0x2b78572feb40, self=174397400, argc=1, argv=0x0, blockptr=0x0, cref=0x0) at vm.c:558 #16 0x00002b785397b037 in vm_yield (val=218460560) at vm.c:588 #17 rb_yield_0 (val=218460560) at vm_eval.c:740 #18 rb_yield (val=218460560) at vm_eval.c:750 #19 0x00002b785383bc9c in rb_ary_each (ary=218460960) at array.c:1427 #20 0x00002b78539716aa in vm_call_cfunc (th=0x8329020, cfp=0x2b78572feb18, num=0, blockptr=0x2b78572feb41, flag=0, id=424, me=0x83dfb90, recv=218460960) at vm_insnhelper.c:402 #21 vm_call_method (th=0x8329020, cfp=0x2b78572feb18, num=0, blockptr=0x2b78572feb41, flag=0, id=424, me=0x83dfb90, recv=218460960) at vm_insnhelper.c:524 #22 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #23 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #24 0x00002b785396b4e5 in vm_call0 (th=0x8329020, recv=180469600, id=384, argc=2, argv=0x7fff7bc67990, me=0xd47b130) at vm_eval.c:66 #25 0x00002b785396d354 in vm_method_missing (th=0x8329020, id=1513486, recv=180469600, num=&lt;value optimized out&gt;, blockptr=0x0, opt=0) ---Type &lt;return&gt; to continue, or q &lt;return&gt; to quit--- at vm_insnhelper.c:448 #26 0x00002b78539715e3 in vm_call_method (th=0x8329020, cfp=0x0, num=1, blockptr=0x0, flag=0, id=5912, me=0x0, recv=180469600) at vm_insnhelper.c:666 #27 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #28 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #29 0x00002b7853970cd9 in invoke_block_from_c (th=0x8329020, block=0x2b78572ffa60, self=218506160, argc=1, argv=0x0, blockptr=0x0, cref=0x0) at vm.c:558 #30 0x00002b785397ad01 in rb_yield_0 (tag=30793742, data=&lt;value optimized out&gt;) at vm.c:588 #31 catch_i (tag=30793742, data=&lt;value optimized out&gt;) at vm_eval.c:1459 #32 0x00002b7853968483 in rb_catch_obj (tag=30793742, func=0x2b785397acc0 &lt;catch_i&gt;, data=0) at vm_eval.c:1534 #33 0x00002b785396978d in rb_f_catch (argc=&lt;value optimized out&gt;, argv=&lt;value optimized out&gt;) at vm_eval.c:1510 #34 0x00002b78539716aa in vm_call_cfunc (th=0x8329020, cfp=0x2b78572ffa38, num=1, blockptr=0x2b78572ffa61, flag=8, id=2840, me=0x83b2250, recv=218506160) at vm_insnhelper.c:402 #35 vm_call_method (th=0x8329020, cfp=0x2b78572ffa38, num=1, blockptr=0x2b78572ffa61, flag=8, id=2840, me=0x83b2250, recv=218506160) at vm_insnhelper.c:524 #36 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #37 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #38 0x00002b785396b4e5 in vm_call0 (th=0x8329020, recv=218506160, id=40296, argc=1, argv=0x7fff7bc685e0, me=0xd47b130) at vm_eval.c:66 #39 0x00002b785396bf9a in rb_call0 (recv=218506160, mid=40296, n=1) at vm_eval.c:235 #40 rb_call (recv=218506160, mid=40296, n=1) at vm_eval.c:438 #41 rb_funcall (recv=218506160, mid=40296, n=1) at vm_eval.c:638 #42 0x00002aaaac565bb6 in event_callback_wrapper (a1=&lt;value optimized out&gt;, a2=&lt;value optimized out&gt;, a3=&lt;value optimized out&gt;, a4=&lt;value optimized out&gt;) at rubymain.cpp:162 #43 0x00002aaaac555688 in ConnectionDescriptor::_DispatchInboundData (this=0xca4a060, buffer=0x7fff7bc654e0 "\001", size=1402620608) at ed.cpp:770 #44 0x00002aaaac55571f in ConnectionDescriptor::Read (this=0xca4a060) at ed.cpp:718 #45 0x00002aaaac55e969 in EventMachine_t::_RunEpollOnce (this=0xc874530) at em.cpp:488 #46 0x00002aaaac55ec46 in EventMachine_t::_RunOnce (this=0xcce4c55) at em.cpp:451 #47 0x00002aaaac55ec93 in EventMachine_t::Run (this=0xc874530) at em.cpp:432 #48 0x00002aaaac565629 in t_run_machine_without_threads (self=214846549) at rubymain.cpp:185 #49 0x00002b78539716aa in vm_call_cfunc (th=0x8329020, cfp=0x2b78572ffbf0, num=0, blockptr=0x1, flag=24, id=39400, me=0x9055d80, recv=139822160) at vm_insnhelper.c:402 #50 vm_call_method (th=0x8329020, cfp=0x2b78572ffbf0, num=0, blockptr=0x1, flag=24, id=39400, me=0x9055d80, recv=139822160) at vm_insnhelper.c:524 #51 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #52 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #53 0x00002b7853979ff7 in rb_iseq_eval (iseqval=145595680) at vm.c:1374 #54 0x00002b785386d741 in rb_load_internal (fname=145597920, wrap=&lt;value optimized out&gt;) at load.c:294 #55 0x00002b785386d8a1 in rb_f_load (argc=&lt;value optimized out&gt;, argv=&lt;value optimized out&gt;) at load.c:367 #56 0x00002b78539716aa in vm_call_cfunc (th=0x8329020, cfp=0x2b78572fff08, num=1, blockptr=0x1, flag=8, id=5944, me=0x8421cd0, recv=137928280) at vm_insnhelper.c:402 #57 vm_call_method (th=0x8329020, cfp=0x2b78572fff08, num=1, blockptr=0x1, flag=8, id=5944, me=0x8421cd0, recv=137928280) ---Type &lt;return&gt; to continue, or q &lt;return&gt; to quit--- at vm_insnhelper.c:524 #58 0x00002b785397438c in vm_exec_core (th=0x8329020, initial=&lt;value optimized out&gt;) at insns.def:1006 #59 0x00002b7853979b99 in vm_exec (th=0xcce4c55) at vm.c:1147 #60 0x00002b7853979e74 in rb_iseq_eval_main (iseqval=145661040) at vm.c:1388 #61 0x00002b785386ae52 in ruby_exec_internal (n=0x8ae9c70) at eval.c:214 #62 0x00002b785386ae79 in ruby_exec_node (n=0x8ae9c70) at eval.c:261 #63 0x00002b785386d1bf in ruby_run_node (n=0x8ae9c70) at eval.c:254 #64 0x00000000004008ef in main (argc=10, argv=0x7fff7bc6df78) at main.c:35 </code></pre> <p>What I can deduce from this:</p> <ul> <li>It's hanging on a regular expression performed on something like <code>52%%20off|utmcmd=email|utmctr=View%20this|utmcct=52%%20off</code>, which appears to be a bastardized form of a query string (any insights on why it's pipes rather than ampersands?). I don't know what the regex they're looking for is, though (any way I can find it?).</li> <li>It's getting through thin/eventmachine just fine to the rails stack just fine because at <code>#42</code>, it seems to be initializing an <code>event_callback_wrapper</code>, which I take to mean that it's handing it off to the next step in Rack.</li> </ul> <p>And a weird thing:</p> <ul> <li><code>netstat</code> doesn't list any outstanding connections, and <code>nginx</code> logs don't show any requests, successful, unsuccessful, or abandoned, with the query string implied by the string that shows up in the backtrace.</li> </ul> <p>Other things I've tried:</p> <p>I've tried just going into gdb and nexting a bunch of times, and it just goes in a loopish manner. I've also tried using <a href="http://www.rubyinside.com/hijack-get-a-live-irb-prompt-for-any-existing-ruby-process-2232.html" rel="nofollow">hijack</a>, but I couldn't find anything useful to do.</p> <p>Things that might be useful that I don't know how to do or whether they are possible:</p> <ul> <li>Get an actual ruby code stack.</li> <li>Figure out what's calling the regex.</li> <li>Nailing down what the regex actually is and what it's being matched against.</li> </ul> <p>Any other advice or whatnot would be greatly appreciated.</p>
    singulars
    1. This table or related slice is empty.
    1. This table or related slice is empty.
    plurals
    1. This table or related slice is empty.
    1. This table or related slice is empty.
    1. This table or related slice is empty.
 

Querying!

 
Guidance

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload