[NSE] qscan first read timeout value too short?

[jah <jah () zadkiel plus com>]

 Hi folks,

Using qscan.nse from winXP with svn r19518 I'm consistently seeing a single packet loss during the script scan. The 
packet 'lost' is the response to the first qscan probe to the first port in the list of ports qscan will probe.  What 
seems to happen is that by the time do_actual_pcap_read is called (for the very first time), the timeout period has 
elapsed and the response is not seen.  Setting NSOCK_TRACE_LEVEL to 10 in nmap.h I get the following output which sheds 
some light on this oddity.

NSOCK (0.1100s) msevent_new (IOD #1) (EID #13)
NSOCK (0.1100s) Pcap read request from IOD #1  EID 13
NSOCK (0.1100s) NSE #13: Adding event
NSOCK (0.1100s) PCAP NSE #13: Adding event to PCAP_READ_EVENTS
SENT (1.2190s) TCP [192.168.1.15:13495 > 212.56.83.200:80 S seq=<snipped the rest>
NSOCK (1.2190s) nsock_loop() started (timeout=50ms). 1 events pending
NSOCK (1.2190s) wait_for_events
NSOCK (1.2190s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.2190s) before iterating, list 0
NSOCK (1.2190s) before iterating, list 1
NSOCK (1.2190s) before iterating, list 2
NSOCK (1.2190s) before iterating, list 3
NSOCK (1.2190s) before iterating, list 4
NSOCK (1.2190s) before iterating 13
NSOCK (1.2190s) list 4, iterating 13
NSOCK (1.2190s) PCAP iterating 13
NSOCK (1.2190s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.2190s) NSE #13: Removing event from event_lists[4]
NSOCK (1.2190s) Callback: READ-PCAP TIMEOUT for EID 13
NSOCK (1.2190s) msevent_delete (IOD #1) (EID #13)
NSOCK (1.2190s) PCAP removed 13

The timeout in this example was about 400 ms and you can probably see that between 'Adding event to PCAP_READ_EVENTS' 
and the call to send_ip_packet (next line) more than a second has elapsed - much more than the timeout.

My attempts at tracking down the source of that one second have been fruitless so far so I'm not sure whether this 
one-time delay is to be expected or if there's something odd going on.  Either way, the very short timeout passed to 
socket.set_timeout in qscan has brought this to light.

The attached patch for qscan could be applied (if the second delay turns-out to be normal) to add a couple of seconds 
to only the very first read and avoid timing out:

NSOCK (0.0930s) msevent_new (IOD #1) (EID #13)
NSOCK (0.0930s) Pcap read request from IOD #1  EID 13
NSOCK (0.0930s) NSE #13: Adding event
NSOCK (0.0930s) PCAP NSE #13: Adding event to PCAP_READ_EVENTS
SENT (1.1090s) TCP [192.168.1.15:13495 > 212.56.83.200:80 S seq=<snipped the rest>csum=0xfb42]
NSOCK (1.1090s) nsock_loop() started (timeout=50ms). 1 events pending
NSOCK (1.1090s) wait_for_events
NSOCK (1.1090s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.1090s) before iterating, list 0
NSOCK (1.1090s) before iterating, list 1
NSOCK (1.1090s) before iterating, list 2
NSOCK (1.1090s) before iterating, list 3
NSOCK (1.1090s) before iterating, list 4
NSOCK (1.1090s) before iterating 13
NSOCK (1.1090s) list 4, iterating 13
NSOCK (1.1090s) PCAP iterating 13
... more do_actual_pcap_read TESTs ...
NSOCK (1.1400s) PCAP do_actual_pcap_read READ (IOD #1) (EID #13) size=60
NSOCK (1.1400s) NSE #13: Removing event from event_lists[4]
NSOCK (1.1400s) Callback: READ-PCAP SUCCESS for EID 13
NSOCK (1.1400s) msevent_delete (IOD #1) (EID #13)
NSOCK (1.1400s) PCAP removed 13



Best,

jah

Attachment: qscan_first_timeout.patch
Description:

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