Re: nping appears to miss or drop a packet when run with newer kernel/libraries

[Paul Blankenbaker <paul.blankenbaker () redali com>]

Thanks for looking into this Luis.

I tried building and running the newer version of nping as instructed. The
newer version appears to be better at getting all of the packets (about 75%
of the time it is successful). However, it appears like there is some sort
of artificial delay between when nping reports the received packet and when
the packet actually returns.

Here is a example run on my Fedora 20 x86_64 based system:

[devel@taco-dev64 nmap-npingchanges]$ sudo nping/nping 192.168.1.2

Starting Nping 0.6.26SVN ( http://nmap.org/nping ) at 2014-01-14 06:47 EST
SENT (0.0000s) IPv4[192.168.1.45 > 192.168.1.2 ttl=64 id=44245 iplen=28]
ICMPv4[Echo request id=29523 seq=0]
SENT (1.0010s) IPv4[192.168.1.45 > 192.168.1.2 ttl=64 id=44246 iplen=28]
ICMPv4[Echo request id=29523 seq=1]
RCVD (1.0020s) IPv4[192.168.1.2 > 192.168.1.45 ttl=64 id=20123 iplen=28]
ICMPv4[Echo reply id=29523 seq=0] Payload[18 bytes]
SENT (2.0010s) IPv4[192.168.1.45 > 192.168.1.2 ttl=64 id=44247 iplen=28]
ICMPv4[Echo request id=29523 seq=2]
RCVD (2.0020s) IPv4[192.168.1.2 > 192.168.1.45 ttl=64 id=20124 iplen=28]
ICMPv4[Echo reply id=29523 seq=1] Payload[18 bytes]
SENT (3.0000s) IPv4[192.168.1.45 > 192.168.1.2 ttl=64 id=44248 iplen=28]
ICMPv4[Echo request id=29523 seq=3]
RCVD (3.0010s) IPv4[192.168.1.2 > 192.168.1.45 ttl=64 id=20125 iplen=28]
ICMPv4[Echo reply id=29523 seq=2] Payload[18 bytes]
SENT (4.0000s) IPv4[192.168.1.45 > 192.168.1.2 ttl=64 id=44249 iplen=28]
ICMPv4[Echo request id=29523 seq=4]
RCVD (4.0010s) IPv4[192.168.1.2 > 192.168.1.45 ttl=64 id=20126 iplen=28]
ICMPv4[Echo reply id=29523 seq=3] Payload[18 bytes]
RCVD (5.0000s) IPv4[192.168.1.2 > 192.168.1.45 ttl=64 id=20127 iplen=28]
ICMPv4[Echo reply id=29523 seq=4] Payload[18 bytes]

Raw packets sent: 5 (140B) | Rcvd: 5 (230B) | Lost: 0 (0.00%)
Max rtt: 1002.464ms | Min rtt: 999.475ms | Avg rtt: 1000.790ms
Nping done: 1 IP address pinged in 8.03 seconds
[devel@taco-dev64 nmap-npingchanges]$


You'll notice that while there are 5 SENT and 5 RCVD packets in this run,
there appears to be a artificial 1 second delay inserted before reporting
the RCVD packet.

Here are the corresponding ICMP packets captured by the dumpcap utility for
nping run above (notice that the RCVD packets occur almost immediately
after the SENT packets - much less than the 1 second delay shown in the
nping output):

2 2.073203000 192.168.1.45 -> 192.168.1.2 ICMP Echo (ping) request
id=0x7353, seq=0/0, ttl=64
3 2.073524000 192.168.1.2 -> 192.168.1.45 ICMP Echo (ping) reply id=0x7353,
seq=0/0, ttl=64 (request in 2)
4 3.074552000 192.168.1.45 -> 192.168.1.2 ICMP Echo (ping) request
id=0x7353, seq=1/256, ttl=64
5 3.075256000 192.168.1.2 -> 192.168.1.45 ICMP Echo (ping) reply id=0x7353,
seq=1/256, ttl=64 (request in 4)
6 4.075013000 192.168.1.45 -> 192.168.1.2 ICMP Echo (ping) request
id=0x7353, seq=2/512, ttl=64
7 4.075368000 192.168.1.2 -> 192.168.1.45 ICMP Echo (ping) reply id=0x7353,
seq=2/512, ttl=64 (request in 6)
8 5.073873000 192.168.1.45 -> 192.168.1.2 ICMP Echo (ping) request
id=0x7353, seq=3/768, ttl=64
9 5.074305000 192.168.1.2 -> 192.168.1.45 ICMP Echo (ping) reply id=0x7353,
seq=3/768, ttl=64 (request in 8)
10 6.073897000 192.168.1.45 -> 192.168.1.2 ICMP Echo (ping) request
id=0x7353, seq=4/1024, ttl=64
11 6.074352000 192.168.1.2 -> 192.168.1.45 ICMP Echo (ping) reply
id=0x7353, seq=4/1024, ttl=64 (request in 10)

Again, thanks for taking the time in looking into this and let me know if
you need additional information or if there is something else you would
like for me to try.

Paul


On Tue, Jan 14, 2014 at 3:16 AM, Luis MartinGarcia. <luis.mgarc () gmail com>wrote:

> Hi Paul,
>
> I have never seen that behaviour in Nping. I have seen Nping missing the
> last reply but never the first one. Could you please download the
> following dev version and try to reproduce the bug?
>
> svn co https://svn.nmap.org/nmap-exp/luis/nmap-npingchanges
>
> Please let me know what results you get.
>
> Thank you and best regards,
>
> Luis MartinGarcia.
>
>
>
> On 12/01/14 17:14, Paul Blankenbaker wrote:
> > We are running into a issue with the nping command when run as the
> > root user (where ICMP packets are used by default). The 6.40 release
> > of the nping command seems to run as expected for us when run on
> > Fedora 18 based systems, but seems to miss a packet when run on Fedora
> > 20 based systems when invoked in the following manner:
> >
> > sudo nping 192.168.1.2
> >
> > We are curious if anyone else has run into a similar issue with the
> > nping utility and if they have found a work around (we could not seem
> > to remedy the problem by adjusting the delay as that only seemed to
> > adjust the delay between subsequent "pings").
> >
> > The following is an example of the output from nping on the problem
> > systems (the first RCVD packet appears to have been missed).
> >
> > [devel@taco-dev64 dev]$ sudo nping 192.168.1.2
> >
> > Starting Nping 0.6.40 ( http://nmap.org/nping ) at 2014-01-12 07:23 EST
> > SENT (0.0168s) ICMP [192.168.1.45 > 192.168.1.2 Echo request
> > (type=8/code=0) id=51556 seq=1] IP [ttl=64 id=10991 iplen=28 ]
> > SENT (1.0240s) ICMP [192.168.1.45 > 192.168.1.2 Echo request
> > (type=8/code=0) id=51556 seq=2] IP [ttl=64 id=10991 iplen=28 ]
> > RCVD (1.0251s) ICMP [192.168.1.2 > 192.168.1.45 Echo reply
> (type=0/code=0)
> > id=51556 seq=1] IP [ttl=64 id=33489 iplen=28 ]
> > SENT (2.0323s) ICMP [192.168.1.45 > 192.168.1.2 Echo request
> > (type=8/code=0) id=51556 seq=3] IP [ttl=64 id=10991 iplen=28 ]
> > RCVD (2.0333s) ICMP [192.168.1.2 > 192.168.1.45 Echo reply
> (type=0/code=0)
> > id=51556 seq=2] IP [ttl=64 id=33490 iplen=28 ]
> > SENT (3.0351s) ICMP [192.168.1.45 > 192.168.1.2 Echo request
> > (type=8/code=0) id=51556 seq=4] IP [ttl=64 id=10991 iplen=28 ]
> > RCVD (3.0379s) ICMP [192.168.1.2 > 192.168.1.45 Echo reply
> (type=0/code=0)
> > id=51556 seq=3] IP [ttl=64 id=33491 iplen=28 ]
> > SENT (4.0409s) ICMP [192.168.1.45 > 192.168.1.2 Echo request
> > (type=8/code=0) id=51556 seq=5] IP [ttl=64 id=10991 iplen=28 ]
> > RCVD (4.0418s) ICMP [192.168.1.2 > 192.168.1.45 Echo reply
> (type=0/code=0)
> > id=51556 seq=4] IP [ttl=64 id=33492 iplen=28 ]
> >
> > Max rtt: 0.600ms | Min rtt: 0.349ms | Avg rtt: 0.460ms
> > Raw packets sent: 5 (140B) | Rcvd: 4 (184B) | Lost: 1 (20.00%)
> > Nping done: 1 IP address pinged in 4.06 seconds
> > [devel@taco-dev64 dev]$
> >
> >
> > In this situation, the nping command appears to have missed the first
> > ICMP packet returned. We ran dumpcap to capture the packets on the
> > wire to see what was going on while the nping command was running. It
> > did appear that nping put out 5 ICMP requests and that 5 ICMP replies
> > came back from the target system (shown below). The first reply was
> > roughly 0.5 milliseconds after the request (not sure if this short
> > duration is meaningful or not).
> >
> > [devel@taco-dev64 dev]$ tcpdump -r ~/Downloads/capture_p2p1.cap
> > reading from file /home/devel/Downloads/capture_p2p1.cap, link-type
> EN10MB
> > (Ethernet)
> > 07:23:25.340951 IP taco-dev64.linux.bogus > rice.linux.bogus: ICMP echo
> > request, id 51556, seq 1, length 8
> > 07:23:25.341459 IP rice.linux.bogus > taco-dev64.linux.bogus: ICMP echo
> > reply, id 51556, seq 1, length 8
> > 07:23:26.348309 IP taco-dev64.linux.bogus > rice.linux.bogus: ICMP echo
> > request, id 51556, seq 2, length 8
> > 07:23:26.348908 IP rice.linux.bogus > taco-dev64.linux.bogus: ICMP echo
> > reply, id 51556, seq 2, length 8
> > 07:23:27.356727 IP taco-dev64.linux.bogus > rice.linux.bogus: ICMP echo
> > request, id 51556, seq 3, length 8
> > 07:23:27.357264 IP rice.linux.bogus > taco-dev64.linux.bogus: ICMP echo
> > reply, id 51556, seq 3, length 8
> > 07:23:28.359328 IP taco-dev64.linux.bogus > rice.linux.bogus: ICMP echo
> > request, id 51556, seq 4, length 8
> > 07:23:28.361343 IP rice.linux.bogus > taco-dev64.linux.bogus: ICMP echo
> > reply, id 51556, seq 4, length 8
> > 07:23:29.365133 IP taco-dev64.linux.bogus > rice.linux.bogus: ICMP echo
> > request, id 51556, seq 5, length 8
> > 07:23:29.365653 IP rice.linux.bogus > taco-dev64.linux.bogus: ICMP echo
> > reply, id 51556, seq 5, length 8
> > [devel@taco-dev64 dev]$
> >
> > I'm not sure as to why nping missed the first packet. Here are some
> > combinations which I've tried that exhibit the issue:
> >
> > On Fedora 20 (kernel: 3.12.6-300.fc20.x86_64), wheter I use Fedora's
> > version of nmap or build nmap from source, the nping utility seems to
> > always miss a packet. Here is the output of "nping -version" and "nmap
> > -version" which shows the libraries linked in.
> >
> > Nping version 0.6.40 ( http://nmap.org/nping )ce the nping comce the
> nping command is the same version on the two systems, I'm at
> > a loss to explain why the behavior is different (unless it has
> > something to do with the newer kernel, libpcre library or libpcap
> > library). Is it possible that a bug in the nping utility has presented
> > itself due to the newer version of the libraries/kernel?mand is the same
> version on the two systems, I'm at
> > a loss to explain why the behavior is different (unless it has
> > something to do with the newer kernel, libpcre library or libpcap
> > library). Is it possible that a bug in the nping utility has presented
> > itself due to the newer version of the libraries/kernel?
> >
> > Nmap version 6.40 ( http://nmap.org )
> > Platform: x86_64-redhat-linux-gnu
> > Compiled with: liblua-5.2.2 openssl-1.0.1e libpcre-8.33 libpcap-1.5.0
> > nmap-libdnet-1.12 ipv6
> > Compiled without:
> > Available nsock engines: epoll poll select
> >
> >
> > I do not see the issue on Fedora 18 (kernel: 3.11.10-100.fc18.i686) I
> > do not see nping dropping any packets. Here is some of the version
> > information I see on this system.
> >
> > Nping version 0.6.40 ( http://nmap.org/nping )
> >
> > Nmap version 6.40 ( http://nmap.org )
> > Platform: i686-redhat-linux-gnu
> > Compiled with: nmap-liblua-5.2.2 openssl-1.0.1e libpcre-8.31
> libpcap-1.3.0
> > nmap-libdnet-1.12 ipv6
> > Compiled without:
> > Available nsock engines: epoll poll select
> >
> >
> > Since the nping command is the same version on the two systems, I'm at
> > a loss to explain why the behavior is different (unless it has
> > something to do with the newer kernel, libpcre library or libpcap
> > library). Is it possible that a bug in the nping utility has presented
> > itself due to the newer version of the libraries/kernel?
> >
> > In any case, if anyone would have some suggestions on what to do to
> > avoid this issue I would appreciate it (it's quite possible I'm just
> > being stupid and missing something obvious - if so I apologize). I can
> > provide more information and/or packet captures if necessary.
> >
> > Thanks,
> > Paul
> > _______________________________________________
> > Sent through the dev mailing list
> > http://nmap.org/mailman/listinfo/dev
> > Archived at http://seclists.org/nmap-dev/
>
> _______________________________________________
> Sent through the dev mailing list
> http://nmap.org/mailman/listinfo/dev
> Archived at http://seclists.org/nmap-dev/
_______________________________________________
Sent through the dev mailing list
http://nmap.org/mailman/listinfo/dev
Archived at http://seclists.org/nmap-dev/