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

[David Fifield <david () bamsoftware com>]

On Tue, Aug 24, 2010 at 12:49:36PM +0100, jah wrote:
>  On 24/08/2010 06:04, David Fifield wrote:
> > On Fri, Aug 20, 2010 at 10:11:13PM +0100, jah wrote:
> > > 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).
> > I've been looking into this. I can reproduce it on Windows XP. What I've
> > found so far is that l_nsock_ncap_register always starts a read event as
> > soon as you call nmap.pcap_register--whether you've done an
> > nmap.pcap_receive yet or not.
> >
> > int l_nsock_ncap_register(lua_State * L)
> > {
> >     ...
> >     /* always create new event. */
> >     nr->nseid = nsock_pcap_read_packet(nsp,
> >             udata->nsiod, l_nsock_pcap_receive_handler, udata->timeout, nr);
> >     ...
> > }
> >
> > Thus it's very possible for this read event to time out before a probe
> > is even sent. Naturally this isn't how anyone expects it to work, and it
> > seems to work fine on Linux. Maybe there is some special conditional
> > Windows code at work. I'll look into it more.
>
> That had me mystified when I saw it; why does it 'always create new
> event' at that point?

It kind of makes sense--you start one read to "prime the pump" then wait
to be called back. ncat_connect.c does something similar where it says
"/* Start the initial reads. */". The timing aspect makes it not quite
right. However I don't think this was the main cause.

I think this is fixed in r19970. This is what I wrote in the log
message.

> Do a gettimeofday to refresh nsock_tod at the top of nsock_pcap_open.
>
> jah found that the first pcap read was always timing out in qscan.nse.
> http://seclists.org/nmap-dev/2010/q3/542. According to the logs, the
> read event was happening around a second before the script's first probe
> was sent, even though the script does things in the opposite order. The
> read event was already long timed out by the time the probe was sent.
> This only happened to the first read.
>
> What was happening was that nsock_tod, Nsock's cache of the
> gettimeofday, was stale. It still had the value it was initialized with
> when nsp_new (via open_nse) was called, even before port scanning was
> done. nsock_tod is updated frequently in nsock_loop but not outside it.
> The first read event was scheduled before nsock_loop was entered, so it
> had the seconds-old timeout, but subsequent reads were fine.
>
> I think we really should be updating nsock_tod when every event is
> added. But I didn't find a good centralized place to do it;
> nsp_add_event already gets an absolute timeout. So I took a cue from the
> connect functions. Outside of nsock_loop, nsock_tod is only updated in
> nsock_connect_*. I think the logic here is that you might wait a while
> before starting a connection, but then subsequent events on the same iod
> will come quickly. The same thing happens with nsock_pcap_open; once you
> open it it's likely that you will start new events soon, so it's a good
> place to update.

Your analysis with the out-of-order times in the log messages was good.
That's what led me to this.

I think it also makes sense to move the unconditional read in
l_ncap_pcap_register. I'll do that if it doesn't look like it will cause
problems.

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