Re: [NSE] qscan first read timeout value too short?

[jah <jah () zadkiel plus com>]

 On 19/08/2010 15:27, Luis MartinGarcia. wrote:
> On 08/07/2010 12:52 AM, David Fifield wrote:
> > Do you think it's related to this recent message?
> >
> > Nsock has trouble handling pcap reads on Windows
> > http://seclists.org/nmap-dev/2010/q3/232
> >
> > Luis found that pcap reads on Windows were not being polled often
> > enough.  His patch was applied in r19487, so you should have the fix
> > already. Luis, you mentioned to me that you confirmed the bug existed
> > with NSE also. Can you reproduce this behavior with qscan?
> >   
> Hi, David,
>
> Sorry for my late reply. I didn't read your message until now.
>
> I did confirm that the bug also affected NSE but I had to cheat a bit in
> order to obtain clear results. A quick explanation is at the end of this
> email [1].
>
> About Qscan, I can't try to reproduce it right now, but I don't think is
> related. The bug I traced did not cause packet loss, it just caused a
> delay on its detection. This is a long shot but I think what we are
> dealing with here is that the script sends a probe, but pcap is not
> ready by the time we receive the first reply.
>
> Also, after a very quick look to the script I see that qscan.nse
> performs certain operations in a different order than ipidseq.nse.  Jah,
> would you try the patch I attach? Sorry if the patch looks absurd, but
> my experience with NSE is close to zero.

Hi Luis,
You are correct about the lost response being unrelated to your changes, I've reproduced this issue on builds from 
revisions prior to yours (which was r19487).
I've tried your patch (which moves the call to pcap_register after sending the probe). It made no difference to the 
result as you can see from the output below. It did however throw-up something potentially interesting (which I haven't 
looked into yet).

This snippet of output is from latest svn (without Luis' patch) and shows the pcap_open, pcap_register, the first qscan 
probe being sent and finally pcap_receive. Note the one second difference in time between the line containing "Adding 
event to PCAP_READ_EVENTS" and the subsequent line "SENT "

NSE: Starting 'qscan' (thread: 0128C570) against 192.168.1.1.
NSOCK (0.0940s) PCAP requested on device ...
NSOCK (0.0940s) PCAP created successfully on device ...
NSOCK (0.0940s) msevent_new (IOD #1) (EID #13)
NSOCK (0.0940s) Pcap read request from IOD #1  EID 13
NSOCK (0.0940s) NSE #13: Adding event
NSOCK (0.0940s) PCAP NSE #13: Adding event to PCAP_READ_EVENTS
SENT (1.0940s) TCP [192.168.1.15:13495 > 192.168.1.1:80 S seq=...
NSOCK (1.0940s) nsock_loop() started (timeout=50ms). 1 events pending
NSOCK (1.0940s) wait_for_events
NSOCK (1.0940s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.0940s) before iterating, list 0
NSOCK (1.0940s) before iterating, list 1
NSOCK (1.0940s) before iterating, list 2
NSOCK (1.0940s) before iterating, list 3
NSOCK (1.0940s) before iterating, list 4
NSOCK (1.0940s) before iterating 13
NSOCK (1.0940s) list 4, iterating 13
NSOCK (1.0940s) PCAP iterating 13
NSOCK (1.0940s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.0940s) NSE #13: Removing event from event_lists[4]
NSOCK (1.0940s) Callback: READ-PCAP TIMEOUT for EID 13
NSOCK (1.0940s) msevent_delete (IOD #1) (EID #13)
NSOCK (1.0940s) PCAP removed 13

The receive timeout was set at 200ms - a period which had elapsed even before the probe was reportedly sent. In this 
next output, with Luis' patch, we can see the probe being sent before pcap_register is called.  There is still a one 
second time difference between "Adding event to PCAP_READ_EVENTS" and the subsequent line, but oddly, the time reported 
for probe send is out of chronological order:

NSE: Starting 'qscan' (thread: 0128C570) against 192.168.1.1.
NSOCK (0.0940s) PCAP requested on device ...
NSOCK (0.0940s) PCAP created successfully on device ...
SENT (1.1090s) TCP [192.168.1.15:13495 > 192.168.1.1:80 S seq=...
NSOCK (0.0940s) msevent_new (IOD #1) (EID #13)
NSOCK (0.0940s) Pcap read request from IOD #1  EID 13
NSOCK (0.0940s) NSE #13: Adding event
NSOCK (0.0940s) PCAP NSE #13: Adding event to PCAP_READ_EVENTS
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
NSOCK (1.1090s) PCAP do_actual_pcap_read TEST (IOD #1) (EID #13)
NSOCK (1.1090s) NSE #13: Removing event from event_lists[4]
NSOCK (1.1090s) Callback: READ-PCAP TIMEOUT for EID 13
NSOCK (1.1090s) msevent_delete (IOD #1) (EID #13)
NSOCK (1.1090s) PCAP removed 13

Needless to say, in both cases the read timed-out and the probe response was 'lost'.

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