How to interpret this `tcpdump` output

arptcpdump

this tcpdump output is the result of sending a single ping package from host 1 to host 2 through a simple hub connection:

root@mininet-vm:~# tcpdump -XX -n -i h2-eth0 
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on h2-eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
00:19:06.466207 ARP, Request who-has 10.0.0.2 tell 10.0.0.1, length 28
        0x0000:  ffff ffff ffff 0000 0000 0001 0806 0001  ................
        0x0010:  0800 0604 0001 0000 0000 0001 0a00 0001  ................
        0x0020:  0000 0000 0000 0a00 0002                 ..........
00:19:06.466285 ARP, Reply 10.0.0.2 is-at 00:00:00:00:00:02, length 28
        0x0000:  0000 0000 0001 0000 0000 0002 0806 0001  ................
        0x0010:  0800 0604 0002 0000 0000 0002 0a00 0002  ................
        0x0020:  0000 0000 0001 0a00 0001                 ..........
00:19:06.468925 IP 10.0.0.1 > 10.0.0.2: ICMP echo request, id 4587, seq 1, length 64
        0x0000:  0000 0000 0002 0000 0000 0001 0800 4500  ..............E.
        0x0010:  0054 ac58 4000 4001 7a4e 0a00 0001 0a00  .T.X@.@.zN......
        0x0020:  0002 0800 7d50 11eb 0001 ea2e f155 0000  ....}P.......U..
        0x0030:  0000 c86b 0600 0000 0000 1011 1213 1415  ...k............
        0x0040:  1617 1819 1a1b 1c1d 1e1f 2021 2223 2425  ...........!"#$%
        0x0050:  2627 2829 2a2b 2c2d 2e2f 3031 3233 3435  &'()*+,-./012345
        0x0060:  3637                                     67
00:19:06.468961 IP 10.0.0.2 > 10.0.0.1: ICMP echo reply, id 4587, seq 1, length 64
        0x0000:  0000 0000 0001 0000 0000 0002 0800 4500  ..............E.
        0x0010:  0054 d17f 0000 4001 9527 0a00 0002 0a00  .T....@..'......
        0x0020:  0001 0000 8550 11eb 0001 ea2e f155 0000  .....P.......U..
        0x0030:  0000 c86b 0600 0000 0000 1011 1213 1415  ...k............
        0x0040:  1617 1819 1a1b 1c1d 1e1f 2021 2223 2425  ...........!"#$%
        0x0050:  2627 2829 2a2b 2c2d 2e2f 3031 3233 3435  &'()*+,-./012345
        0x0060:  3637                                     67
00:19:11.471904 ARP, Request who-has 10.0.0.1 tell 10.0.0.2, length 28
        0x0000:  0000 0000 0001 0000 0000 0002 0806 0001  ................
        0x0010:  0800 0604 0001 0000 0000 0002 0a00 0002  ................
        0x0020:  0000 0000 0000 0a00 0001                 ..........
00:19:11.509755 ARP, Reply 10.0.0.1 is-at 00:00:00:00:00:01, length 28
        0x0000:  0000 0000 0002 0000 0000 0001 0806 0001  ................
        0x0010:  0800 0604 0002 0000 0000 0001 0a00 0001  ................
        0x0020:  0000 0000 0002 0a00 0002                 ..........

I am a little puzzled about the order of the output.
I would have assumed the order

ARP-request host 1 to host 2
ARP-reply host 2 to host 1
ICMP echo request host 1 to host 2
ARP-request host 2 to host 1
ARP-reply host 1 to host 2
ICMP echo reply host 2 to host 1

but tcpdump shows the order

ARP-request host 1 to host 2
ARP-reply host 2 to host 1
ICMP echo request host 1 to host 2
ICMP echo reply host 2 to host 1
ARP-request host 2 to host 1
ARP-reply host 1 to host 2

which I don't understand.

My assumption here is, that before echo-replying through ICMP, host 2 has to request host 1's MAC address by using ARP.

What am I getting wrong?

Or is tcpdump simply changing the order in its ouput format, so that ICMP-request and reply are not far apart in tcpdump's output?

UPDATE:
All hosts and the network hub are running Ubuntu 14.04 with kernel 3.13.0-24-generic ( to be more precise: I am running a VM inside which I am running mininet with a hub-star-topology).

Best Answer

Your assumptions are flawed.

When host 2 receives the ARP request from host 1, in addition to sending the ARP reply it should also update/add the entry for host 1 in it's own ARP table.

So your order should be extended to look more like this:

ARP-request host 1 to host 2
Host 2 updates or adds entry for host 1 in ARP table
ARP-reply host 2 to host 1
Host 1 adds entry for host 2 in ARP table
ICMP echo request host 1 to host 2
ICMP echo reply host 2 to host 1

As to why host 2 sends out an ARP request so soon after, I would guess that the OS you are using either keeps a short timer for entries added this way and sends an ARP request to minimize the impact of any potential ARP poisoning attacks. However this is only a guess and it would take looking into what the OS is actually doing to make sure.

For more detail on the ARP process, you can check out RFC 826. Here is the processing flow from the RFC:

Packet Reception:
-----------------

When an address resolution packet is received, the receiving
Ethernet module gives the packet to the Address Resolution module
which goes through an algorithm similar to the following.
Negative conditionals indicate an end of processing and a
discarding of the packet.

?Do I have the hardware type in ar$hrd?
Yes: (almost definitely)
  [optionally check the hardware length ar$hln]
  ?Do I speak the protocol in ar$pro?
  Yes:
    [optionally check the protocol length ar$pln]
    Merge_flag := false
    If the pair <protocol type, sender protocol address> is
        already in my translation table, update the sender
        hardware address field of the entry with the new
        information in the packet and set Merge_flag to true.
    ?Am I the target protocol address?
    Yes:
      If Merge_flag is false, add the triplet <protocol type,
          sender protocol address, sender hardware address> to
          the translation table.
      ?Is the opcode ares_op$REQUEST?  (NOW look at the opcode!!)
      Yes:
        Swap hardware and protocol fields, putting the local
            hardware and protocol addresses in the sender fields.
        Set the ar$op field to ares_op$REPLY
        Send the packet to the (new) target hardware address on
            the same hardware on which the request was received.
Related Topic