Re: Weird Crash - "WAITING_TO_RUNNING"

[Nathan <nathan.stocks () gmail com>]

On Fri, Dec 3, 2010 at 5:49 PM, David Fifield <david () bamsoftware com> wrote:
> On Fri, Dec 03, 2010 at 11:17:49AM -0700, Nathan wrote:
> > On Tue, Nov 23, 2010 at 2:59 PM, David Fifield <david () bamsoftware com> wrote:
> > > I looked over the code and I can't find what might be causing the change
> > > in run time. I attached four different versions of nse_main.lua that
> > > make incremental changes. Please try running each of the four and report
> > > the times you get. Just copy each one over nse_main.lua in turn.
> > >
> > > David Fifield
> >
> > Sorry for the delay, it's been a very busy work week.  Here are the
> > measurements you asked for with your custom versions of nse_main.lua.
> > Please note that the values will fluctuate ~2% from run to run, but
> > within about that margin of error the runs were very consistent with
> > themselves.  Also, these were all run with nmap 5.35DC1, with
> > nse_main.lua replaced by the file indicated.
> >
> > nse_main.lua.1: 53732 kB RAM, 5m40s
> >
> > nse_main.lua.2: 53588 kB RAM, 5m21s
> >
> > nse_main.lua.3: 55512 kB RAM, 5m27s
> >
> > nse_main.lua.4: 54352 kB RAM, 5m22s
> >
> > Since none of those seem to display any problems, I went and ran a
> > bunch of other things:
> >
> > 1) Here's the nse_main.lua pulled from 5.36TEST2 and copied over into 5.35DC1
> >
> > 54448 kB RAM, 5m23s
> >
> > 2) Same as #1, but with the CONCURRENCY_LIMIT lowered to 100
> >
> > 54312 kB RAM, 5m32.126s
> >
> > 3) Here's the vanilla nmap 5.36TEST2 on the same machine (when I run
> > this one, I compile it but don't install it, then I run it from the
> > directory it was compiled in).
> >
> > 94532 kB RAM, 14m48s
>
> When you are running from the same directory, do you use "--datadir ."?
> If not, it might be referring to the wrong nse_main.lua (the installed
> one). Try your command with
>
> nmap --datadir . <args..>
>
> > So what really mystifies me is #1 up there.  It's the nse_main.lua
> > from 5.36TEST2 with a CONCURRENCY_LIMIT of 1000, and yet it seems to
> > run fine.  And then that same file running under nmap 5.36TEST2
> > performs horribly.  Perhaps the problem is with some other change in
> > 5.36TEST2, and not in nse_main.lua.
> >
> > Please let me know if you would like me to try anything else out.
>
> I looked through the logs and identified revisions that are more likely
> to have changed something in NSE betweern 5.35DC1 and 5.36TEST1. I know
> this is asking a lot, but if the --datadir doesn't solve it, please try
> building and testing each of these revisions:
>
> 19514 19515 20266 20267 20632 20633
>
> Starting from a Subversion checkout, you will run
>
> svn update --ignore-externals -r 19514 . nbase ncat nping nsock zenmap
>
> Then build and test, using "--datadir .". Then move on to 19515, 20266,
> etc. (You don't have to check out again every time.)
>
> David Fifield

No, I was not using "--datadir ." before.

NOW for the long-awaited testing:

Here's the command I used to set up nmap each time (from an svn checkout):

$ svn update --ignore-externals -r $REVISION . nbase ncat nping nsock
zenmap && make clean && ./configure && make

Here's the command I'm using to test each of the versions you indicated:

$ time /usr/bin/sudo ./nmap --datadir . -sS -sV -T4 -p 1-65535
74.62.92.70 -P0 -v

...while in a separate shell I run the following command to see the
total RAM usage at the END of the run (obviously RAM usage varies
quite a bit during the run):

$ while /bin/true ; do sleep 1 && echo "---------" && date && cat
/proc/meminfo  | grep MemFree ; done

Note that nothing else is running on the box at the time except my SSH
session to it.

==> r19514: <==

Elapsed time: 14m12s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 12:42, 152.10s elapsed (65535 total ports)
Initiating Service scan at 12:42
Scanning 64903 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.50% done; ETC: 12:47 (0:03:58 remaining)
Service scan Timing: About 22.80% done; ETC: 12:47 (0:03:27 remaining)
Service scan Timing: About 34.37% done; ETC: 12:47 (0:02:54 remaining)
Service scan Timing: About 45.97% done; ETC: 12:47 (0:02:22 remaining)
Service scan Timing: About 57.62% done; ETC: 12:47 (0:01:51 remaining)
Service scan Timing: About 69.10% done; ETC: 12:47 (0:01:21 remaining)
Service scan Timing: About 80.80% done; ETC: 12:47 (0:00:50 remaining)
Completed Service scan at 12:47, 260.47s elapsed (64911 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 12:47
NSE Timing: About 1.34% done; ETC: 13:25 (0:38:00 remaining)
NSE Timing: About 2.78% done; ETC: 13:24 (0:35:33 remaining)
NSE Timing: About 5.00% done; ETC: 13:22 (0:33:32 remaining)
NSE Timing: About 7.88% done; ETC: 13:21 (0:31:45 remaining)
NSE Timing: About 11.15% done; ETC: 13:21 (0:30:00 remaining)
NSE Timing: About 14.59% done; ETC: 13:20 (0:28:12 remaining)
NSE Timing: About 18.12% done; ETC: 13:19 (0:26:30 remaining)
NSE Timing: About 21.65% done; ETC: 13:19 (0:24:51 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

==> r19515 <==

Elapsed time: 13m31s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 13:04, 72.54s elapsed (65535 total ports)
Initiating Service scan at 13:04
Scanning 65210 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.49% done; ETC: 13:08 (0:03:59 remaining)
Service scan Timing: About 22.62% done; ETC: 13:08 (0:03:29 remaining)
Service scan Timing: About 33.83% done; ETC: 13:08 (0:02:58 remaining)
Service scan Timing: About 45.26% done; ETC: 13:08 (0:02:26 remaining)
Service scan Timing: About 56.39% done; ETC: 13:08 (0:01:57 remaining)
Service scan Timing: About 68.05% done; ETC: 13:08 (0:01:25 remaining)
Service scan Timing: About 79.54% done; ETC: 13:08 (0:00:54 remaining)
Completed Service scan at 13:08, 263.21s elapsed (65218 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 13:09
NSE Timing: About 1.11% done; ETC: 13:55 (0:46:07 remaining)
NSE Timing: About 2.44% done; ETC: 13:50 (0:40:35 remaining)
NSE Timing: About 4.30% done; ETC: 13:49 (0:38:12 remaining)
NSE Timing: About 6.75% done; ETC: 13:48 (0:36:11 remaining)
NSE Timing: About 9.81% done; ETC: 13:47 (0:34:11 remaining)
NSE Timing: About 13.13% done; ETC: 13:46 (0:32:12 remaining)
NSE Timing: About 16.59% done; ETC: 13:45 (0:30:16 remaining)
NSE Timing: About 20.17% done; ETC: 13:44 (0:28:22 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

==> r20266 <==

Elapsed time: 14m36s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 14:43, 149.50s elapsed (65535 total ports)
Initiating Service scan at 14:43
Scanning 63650 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.06% done; ETC: 14:48 (0:04:09 remaining)
Service scan Timing: About 22.43% done; ETC: 14:48 (0:03:31 remaining)
Service scan Timing: About 33.84% done; ETC: 14:48 (0:02:58 remaining)
Service scan Timing: About 45.47% done; ETC: 14:48 (0:02:25 remaining)
Service scan Timing: About 57.29% done; ETC: 14:48 (0:01:53 remaining)
Service scan Timing: About 69.17% done; ETC: 14:48 (0:01:21 remaining)
Service scan Timing: About 80.99% done; ETC: 14:48 (0:00:50 remaining)
Completed Service scan at 14:47, 258.57s elapsed (63658 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 14:48
NSE Timing: About 1.27% done; ETC: 15:29 (0:40:11 remaining)
NSE Timing: About 2.64% done; ETC: 15:26 (0:37:30 remaining)
NSE Timing: About 4.74% done; ETC: 15:25 (0:35:29 remaining)
NSE Timing: About 7.75% done; ETC: 15:24 (0:33:32 remaining)
NSE Timing: About 11.16% done; ETC: 15:23 (0:31:35 remaining)
NSE Timing: About 14.53% done; ETC: 15:23 (0:29:48 remaining)
NSE Timing: About 19.68% done; ETC: 15:23 (0:28:02 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

==> r20267 <==

Elapsed time: 13m58s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 15:05, 109.18s elapsed (65535 total ports)
Initiating Service scan at 15:05
Scanning 64907 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.21% done; ETC: 15:10 (0:04:06 remaining)
Service scan Timing: About 22.53% done; ETC: 15:10 (0:03:30 remaining)
Service scan Timing: About 33.98% done; ETC: 15:10 (0:02:57 remaining)
Service scan Timing: About 45.62% done; ETC: 15:10 (0:02:24 remaining)
Service scan Timing: About 57.15% done; ETC: 15:10 (0:01:53 remaining)
Service scan Timing: About 68.85% done; ETC: 15:10 (0:01:22 remaining)
Service scan Timing: About 80.31% done; ETC: 15:10 (0:00:52 remaining)
Completed Service scan at 15:10, 260.84s elapsed (64915 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 15:10
NSE Timing: About 1.18% done; ETC: 15:54 (0:43:16 remaining)
NSE Timing: About 2.49% done; ETC: 15:51 (0:39:48 remaining)
NSE Timing: About 4.72% done; ETC: 15:50 (0:37:41 remaining)
NSE Timing: About 7.44% done; ETC: 15:49 (0:35:40 remaining)
NSE Timing: About 10.52% done; ETC: 15:48 (0:33:44 remaining)
NSE Timing: About 13.86% done; ETC: 15:47 (0:31:47 remaining)
NSE Timing: About 17.47% done; ETC: 15:46 (0:29:50 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

real    13m58.154s
user    7m47.193s
sys     0m5.656s

==> r20632 <==

Elapsed time: 14m21s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 15:28, 71.62s elapsed (65535 total ports)
Initiating Service scan at 15:28
Scanning 65213 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.87% done; ETC: 15:32 (0:03:50 remaining)
Service scan Timing: About 23.28% done; ETC: 15:32 (0:03:21 remaining)
Service scan Timing: About 34.86% done; ETC: 15:32 (0:02:50 remaining)
Service scan Timing: About 46.59% done; ETC: 15:32 (0:02:19 remaining)
Service scan Timing: About 58.29% done; ETC: 15:32 (0:01:48 remaining)
Service scan Timing: About 69.80% done; ETC: 15:32 (0:01:18 remaining)
Service scan Timing: About 81.37% done; ETC: 15:32 (0:00:48 remaining)
Completed Service scan at 15:32, 258.71s elapsed (65221 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 15:33
NSE Timing: About 0.98% done
NSE Timing: About 2.09% done; ETC: 16:22 (0:47:41 remaining)
NSE Timing: About 3.56% done; ETC: 16:20 (0:45:13 remaining)
NSE Timing: About 5.97% done; ETC: 16:18 (0:42:48 remaining)
NSE Timing: About 9.03% done; ETC: 16:17 (0:40:26 remaining)
NSE Timing: About 12.33% done; ETC: 16:16 (0:38:10 remaining)
NSE Timing: About 15.75% done; ETC: 16:16 (0:35:55 remaining)
NSE Timing: About 19.18% done; ETC: 16:15 (0:33:47 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

real    14m21.739s
user    8m49.969s
sys     0m3.316s

==> r20633 <==

Elapsed time: 13m5s
Memory usage: 4GB (crashed)

output that matters:
Completed SYN Stealth Scan at 15:45, 57.71s elapsed (65535 total ports)
Initiating Service scan at 15:45
Scanning 65212 services on remote.tjwels.net (74.62.92.70)
Service scan Timing: About 11.46% done; ETC: 15:49 (0:03:59 remaining)
Service scan Timing: About 23.01% done; ETC: 15:49 (0:03:24 remaining)
Service scan Timing: About 34.78% done; ETC: 15:49 (0:02:51 remaining)
Service scan Timing: About 46.38% done; ETC: 15:49 (0:02:20 remaining)
Service scan Timing: About 58.06% done; ETC: 15:49 (0:01:49 remaining)
Service scan Timing: About 69.78% done; ETC: 15:49 (0:01:18 remaining)
Service scan Timing: About 81.44% done; ETC: 15:49 (0:00:48 remaining)
Completed Service scan at 15:49, 258.35s elapsed (65220 services on 1 host)
NSE: Script scanning 74.62.92.70.
NSE: Starting runlevel 1 (of 1) scan.
Initiating NSE at 15:50
NSE Timing: About 1.17% done; ETC: 16:34 (0:43:37 remaining)
NSE Timing: About 2.44% done; ETC: 16:31 (0:40:40 remaining)
NSE Timing: About 4.26% done; ETC: 16:30 (0:38:35 remaining)
NSE Timing: About 7.15% done; ETC: 16:29 (0:36:33 remaining)
NSE Timing: About 14.41% done; ETC: 16:30 (0:34:33 remaining)
nse_restore: WAITING_TO_RUNNING error!
not enough memory
QUITTING!
Realloc Failed! Probably out of space.
QUITTING!

real    13m5.331s
user    7m48.253s
sys     0m4.404s

-------------

So what in the world did I miss?  Is this "--data_dir ." option
messing things up?  I wouldn't expect any crashes in revisions after
the nse_main.lua change...and yet they're all crashing.  The 'svn
updates' always had at least a decent number of files listed as having
been modified in the update.

Perhaps I'm doing something wrong in my build process?

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