Re: Help debugging hang with epoll_engine

[Daniel Miller <bonsaiviking () gmail com>]

On 06/07/2012 01:09 PM, Daniel Miller wrote:
> List,
>
> I think this may be the same issue I reported here: 
> http://seclists.org/nmap-dev/2012/q1/435
>
> This time, I was doing a large IPv6 scan (sudo ./nmap -6 -d2 -oA 
> ../top-1m-v6 -A -iL alexa-top-1m --log-errors -T4), which hung on NSE 
> scanning:
>
> > NSE Timing: About 99.24% done; ETC: 12:38 (0:00:19 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:39 (0:00:19 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:39 (0:00:20 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:40 (0:00:20 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:40 (0:00:20 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:41 (0:00:20 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:41 (0:00:21 remaining)
> > NSE Timing: About 99.24% done; ETC: 12:42 (0:00:21 remaining)
> This time, I was running under sudo, which meant I couldn't get a 
> traceback or detailed status line due to the issue in this thread: 
> http://seclists.org/nmap-dev/2011/q3/413 (confirmed in this thread: 
> http://seclists.org/nmap-dev/2012/q2/44)
>
> I was, however, able to attach with strace, which contained lots of 
> repetitions of these calls:
>
> > gettimeofday({1339090519, 54857}, NULL) = 0
> > ioctl(4, TIOCGPGRP, [135333485])        = -1 ENOTTY (Inappropriate 
> > ioctl for device)
> > gettimeofday({1339090519, 55094}, NULL) = 0
> > gettimeofday({1339090519, 55202}, NULL) = 0
> > epoll_wait(7, {}, 128, 50)              = 0
> > gettimeofday({1339090519, 105501}, NULL) = 0
> > gettimeofday({1339090519, 105596}, NULL) = 0
> > ioctl(4, TIOCGPGRP, [135333485])        = -1 ENOTTY (Inappropriate 
> > ioctl for device)
> > gettimeofday({1339090519, 105835}, NULL) = 0
> The epoll_wait call led me to the epoll_loop function in 
> nsock/src/engine_epoll.c, but the loop must be higher up, since 
> epoll_wait is returning 0, and the condition of the inner loop is on 
> its return value being -1.
>
> I'll be testing this with a debug build, and try to get a full 
> backtrace (NSE and C), but I thought perhaps someone could reason 
> something out from this.
>
> Dan
Ok, I did a debug build, and I've traced the loop to somewhere in 
Lua-land, but I can't figure it out. Here are some relevant excerpts 
from my debug session:

> NSE Timing: About 98.75% done; ETC: 13:28 (0:00:05 remaining)
> NSE: Waiting: 'http-title' (thread: 0x9ac3a18)
>         stack traceback:
>                 [C]: in function 'connect'
>                 ./nselib/dns.lua:91: in function 'sendPackets'
>                 ./nselib/dns.lua:320: in function 'query'
>                 ./scripts/http-title.nse:180: in function 'is_vhost'
>                 ./scripts/http-title.nse:116: in function 'rule'
>                 ./scripts/http-title.nse:158: in function 'redirect_ok'
>                 ./scripts/http-title.nse:57: in function 
> <./scripts/http-title.nse:47>
>                 (...tail calls...)
> Program received signal SIGINT, Interrupt.
> 0x00132416 in __kernel_vsyscall ()
> (gdb) bt
> #0  0x00132416 in __kernel_vsyscall ()
> #1  0x005c6658 in __epoll_wait_nocancel () at 
> ../sysdeps/unix/syscall-template.S:82
> #2  0x082684da in epoll_loop (nsp=0x8c5ac10, msec_timeout=50) at 
> engine_epoll.c:287
> #3  0x08262768 in nsock_loop (nsp=0x8c5ac10, msec_timeout=50) at 
> nsock_core.c:909
> #4  0x08240e71 in l_loop (L=0x8c56ad8) at nse_nsock.cc:401
> #5  0x082878d9 in luaD_precall (L=0x8c56ad8, func=0x99497a0, 
> nresults=0) at ldo.c:317
> #6  0x082a528e in luaV_execute (L=0x8c56ad8) at lvm.c:702
> #7  0x08287fb4 in luaD_call (L=0x8c56ad8, func=0x99496c8, nResults=0, 
> allowyield=0) at ldo.c:393
> #8  0x082825da in lua_callk (L=0x8c56ad8, nargs=2, nresults=0, ctx=0, 
> k=0) at lapi.c:902
> #9  0x0823b80f in run_main (L=0x8c56ad8) at nse_main.cc:418
> #10 0x082878d9 in luaD_precall (L=0x8c56ad8, func=0x99496b8, 
> nresults=0) at ldo.c:317
> #11 0x08287f6b in luaD_call (L=0x8c56ad8, func=0x99496b8, nResults=0, 
> allowyield=0) at ldo.c:392
> #12 0x082826c9 in f_call (L=0x8c56ad8, ud=0xbfffebb8) at lapi.c:920
> #13 0x08286a9e in luaD_rawrunprotected (L=0x8c56ad8, f=0x8282676 
> <f_call>, ud=0xbfffebb8) at ldo.c:131
> #14 0x08288ccf in luaD_pcall (L=0x8c56ad8, func=0x8282676 <f_call>, 
> u=0xbfffebb8, old_top=16, ef=8) at ldo.c:591
> #15 0x082827f5 in lua_pcallk (L=0x8c56ad8, nargs=1, nresults=0, 
> errfunc=1, ctx=0, k=0) at lapi.c:946
> #16 0x0823c60e in script_scan (targets=..., scantype=SCRIPT_SCAN) at 
> nse_main.cc:571
> #17 0x080cfa4f in nmap_main (argc=8, argv=0xbffff744) at nmap.cc:1991
> #18 0x080c1121 in main (argc=8, argv=0xbffff744) at main.cc:198
> (gdb) break nse_nsock.cc:402
> Breakpoint 4 at 0x8240e5f: file nse_nsock.cc, line 401.
> (gdb) cont
> Continuing.
>
> Breakpoint 4, l_loop (L=0x8c56ad8) at nse_nsock.cc:401
> #I'll just put the source lines here. Stepped through with "n"
> 401      if (nsock_loop(nsp, tout) == NSOCK_LOOP_ERROR)
> 403      return 0;
> 404    }
>
> luaD_precall (L=0x8c56ad8, func=0x99497a0, nresults=0) at ldo.c:320
> 320          luaD_poscall(L, L->top - n);
> 321          return 1;
> 350    }
>
> luaV_execute (L=0x8c56ad8) at lvm.c:858
> # This is the body of the interpreter loop. I'll just list the opcodes 
> from here to
> # the next breakpoint
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_JMP
> OP_TFORCALL
> OP_TFORLOOP
> OP_GETUPVAL
> OP_LOADK
> OP_CALL
> OP_JMP
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_TEST
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_TEST
> OP_TEST
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_LOADK
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_JMP
> OP_TFORCALL
> OP_TFORLOOP
> OP_RETURN
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_LOADK
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_JMP
> OP_TFORCALL
> OP_TFORLOOP
> OP_ADD
> OP_TFORCALL
> OP_TFORLOOP
> OP_RETURN
> OP_GETTABUP
> OP_CALL
> OP_TEST
> OP_MOVE
> OP_LOADK
> OP_CALL
> OP_TEST
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_JMP
> OP_TFORCALL
> OP_TFORLOOP
> OP_SELF
> OP_CALL
> OP_GETTABLE
> OP_EQ
> OP_GETTABLE
> OP_EQ
> OP_GETTABUP
> OP_GETTABLE
> OP_TAILCALL
> OP_RETURN
> OP_TEST
> OP_TFORCALL
> OP_TFORLOOP
> OP_GETUPVAL
> OP_MOVE
> OP_CALL
> OP_JMP
> OP_TFORCALL
> OP_TFORLOOP
> OP_GETUPVAL
> OP_LOADK
> OP_CALL
> Breakpoint 4, l_loop (L=0x8c56ad8) at nse_nsock.cc:401

I hope someone can figure out from the opcodes and backtraces which 
section of Lua code is caught in an infinite loop here.

Dan

_______________________________________________
Sent through the nmap-dev mailing list
http://cgi.insecure.org/mailman/listinfo/nmap-dev
Archived at http://seclists.org/nmap-dev/