NSE using 100% CPU and effectively hanging until timeout

[Brandon Enright <bmenrigh () ucsd edu>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Rather than chain a bunch of issues into one long thread, I'll start a
new one regarding NSE behaving oddly.

I was seeing a memory-leak or runaway memory usage issue that I have
not been able to reproduce.  Now I'm seeing a semi-reproducible NSE
issue where the Nmap process starts using 100% and NSE stops doing
useful work.

If I scan a handful of hosts (6) with --script=all NSE makes
progress and then suddenly the Nmap process starts using 100% CPU and
NSE hangs.  I decided to increase verbosity and debug info when I saw
it happen.  Nothing but host timeouts was printed even with the
debugging way up:

SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:43 (0:00:30 remaining)
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:44 (0:00:34 remaining)
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:44 (0:00:37 remaining)
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:45 (0:00:40 remaining)
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:45 (0:00:44 remaining)
Debugging Increased to 2.
Debugging Increased to 3.
Debugging Increased to 4.
Debugging Increased to 5.
Debugging Increased to 6.
Debugging Increased to 7.
Debugging Increased to 8.
Debugging Increased to 9.
Debugging Increased to 10.
Stats: 0:21:26 elapsed; 0 hosts completed (6 up), 6 undergoing Script Scan
Active NSE scripts: 30
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:46 (0:00:46 remaining)
Verbosity Increased to 3.
Verbosity Increased to 4.
Verbosity Increased to 5.
Verbosity Increased to 6.
Verbosity Increased to 7.
Verbosity Increased to 8.
Verbosity Increased to 9.
Verbosity Increased to 10.
Verbosity Increased to 11.
Stats: 0:21:29 elapsed; 0 hosts completed (6 up), 6 undergoing Script Scan
Active NSE scripts: 30
SCRIPT ENGINE Timing: About 89.80% done; ETC: 01:46 (0:00:47 remaining)
SCRIPT ENGINE (1291.975s): Stopped ./scripts/banner.nse against a.b.1.47:10101 (thread 0x7953980) because of host 
timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/rpcinfo.nse against a.b.1.47:1003 (thread 0x7a0e130) because of host 
timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/banner.nse against a.b.1.47:1003 (thread 0x7a08f50) because of host 
timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/pop3-brute.nse against a.b.1.47:995 (thread 0x79ee0f0) because of host 
timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/banner.nse against a.b.1.47:993 (thread 0x79e1900) because of host timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/banner.nse against a.b.1.47:514 (thread 0x7994b60) because of host timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/sslv2.nse against a.b.1.47:443 (thread 0x7982840) because of host timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/banner.nse against a.b.1.47:110 (thread 0x78e6ac0) because of host timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/http-auth.nse against a.b.1.47:80 (thread 0x789ad70) because of host 
timeout.
SCRIPT ENGINE (1291.975s): Stopped ./scripts/robots.txt.nse against a.b.1.47:80 (thread 0x789e590) because of host 
timeout.
SCRIPT ENGINE Timing: About 93.20% done; ETC: 01:46 (0:00:32 remaining)
SCRIPT ENGINE Timing: About 93.20% done; ETC: 01:47 (0:00:34 remaining)
SCRIPT ENGINE (1362.817s): Stopped ./scripts/auth-owners.nse against a.b.1.90:2049 (thread 0x7871060) because of host 
timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/skypev2-version.nse against a.b.1.90:875 (thread 0x7964960) because of 
host timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/rpcinfo.nse against a.b.1.90:700 (thread 0x79476a0) because of host 
timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/auth-owners.nse against a.b.1.90:699 (thread 0x792fc80) because of host 
timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/auth-owners.nse against a.b.1.90:587 (thread 0x791c890) because of host 
timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/banner.nse against a.b.1.90:105 (thread 0x78690a0) because of host timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/http-trace.nse against a.b.1.90:80 (thread 0x777f620) because of host 
timeout.
SCRIPT ENGINE (1362.817s): Stopped ./scripts/banner.nse against a.b.1.90:80 (thread 0x76cbb20) because of host timeout.
SCRIPT ENGINE Timing: About 95.92% done; ETC: 01:47 (0:00:21 remaining)
...this goes on with hosts timing out...

Normally with a really high debugging NSOCK events get printed to the
screen.  Whatever Nmap/NSE was doing during this time, no interesting
debug info was printed.

Is there a way I can figure out what scripts are running or what the
script engine is doing during this time?  Would doing something like
attaching GDB to the running process when I see the issue happen work?
I've never tried to debug a running process on Linux.

Brandon

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.9 (GNU/Linux)

iEYEARECAAYFAkmHpIwACgkQqaGPzAsl94LJ0QCffG8/LbOfyXk3B4/J4f8IyUwP
5DgAn2cG3P2B6xAEYtTlcrzqYh64aZSp
=BkGQ
-----END PGP SIGNATURE-----

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