Apr 132014
 

I started seeing this recently. It appears in the logs on my firewall:

Apr 13 16:02:36 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 16:03:15 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0
Apr 13 16:12:26 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 16:13:04 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0
Apr 13 16:22:16 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 16:22:55 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0
Apr 13 16:32:06 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0

It does not seem to be disturbing anything, other than my nerves.

The classical situation is: two PCs are arguing over the same IP address. Each NIC has a unique MAC address, used at the physical network segment. We often refer to IP addresses in a computer network that uses the Internet Protocol (IP) for communication.

Let’s look closely at this.

Who is this?

The MAC address will identify the manufacturer. Using any of a number of tools, such as MAC Address Lookup, I found:

  • 78:ca:39:fe:d6:b3 – Apple
  • 14:99:e2:27:0f:48 – No Vendor Exists

So we know we’re talking about one of a number of Apple devices, and something else.

DHCP

Let’s look at at my DHCP server. in /usr/local/etc/dhcpd.conf, I found this entry:

       # Apple-TV
        host Apple-TV { 
                hardware ethernet 14:99:e2:27:0f:48;
                fixed-address Apple-TV.unixathome.org;
        }

I do have an Apple TV, but I’m not at home while I write this, so I cannot confirm the MAC address on that unit. Clearly, it is correct because arp is complaining about it.

I initially did not find 78:ca:39:fe:d6:b3 in my DHCP configuration. Then I did a case-insensitive search. I found:

        # time machine
        host tardis {   
                hardware ethernet 78:CA:39:FE:D6:B3;
                fixed-address 10.55.0.63;
        }

OK, two entries, both fighting over 10.55.0.62. How can that be? One is fixed to 10.55.0.63 and the other is clearly 10.55.0.62:

$ host Apple-TV.unixathome.org
Apple-TV.unixathome.org has address 10.55.0.62

Checking DNS

What about DNS:

$ host 10.55.0.63
63.0.55.10.in-addr.arpa domain name pointer tardis.unixathome.org.

$ host tardis.unixathome.org
tardis.unixathome.org has address 10.55.0.63

That looks right. At least it is consistent.

$ host Apple-TV.unixathome.org
Apple-TV.unixathome.org has address 10.55.0.62
$ host 10.55.0.62
Host 62.0.55.10.in-addr.arpa. not found: 3(NXDOMAIN)

Hmm. I should fix that, but I doubt that has anything to do with the problem.

I looked at the zone file on my DNS server. I found an entry for 10.55.0.62, but found an old SERIAL number. I updated the serial number and issued a service named reload command. After that, both forward and reverse DNS worked:

$ host 10.55.0.62
62.0.55.10.in-addr.arpa domain name pointer Apple-TV.unixathome.org.

$ host Apple-TV.unixathome.org
Apple-TV.unixathome.org has address 10.55.0.62

Checking for the problem

Now let’s see if the problem recurs. This shouldn’t take long:

$ tail -F /var/log/messages | grep moved
Apr 13 18:30:06 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 18:30:44 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0
Apr 13 18:39:56 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 18:40:34 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0
Apr 13 18:49:46 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
Apr 13 18:50:21 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0

No, that did not fix it. But then, I did not think it would.

More logs

I did not think to look at the logs on the DHCP server because any anomalies should be coming through via logcheck. When I did look, I found:

$ grep dhcp /var/log/messages
Apr 13 18:30:07 toiler dhcpd: uid lease 10.55.0.217 for client 14:99:e2:27:0f:48 is duplicate on 10.55.0.0/24
Apr 13 18:30:07 toiler dhcpd: Unable to add reverse map from 62.0.55.10.in-addr.arpa. to Apple-TV.unixathome.org: REFUSED
Apr 13 18:39:58 toiler dhcpd: uid lease 10.55.0.217 for client 14:99:e2:27:0f:48 is duplicate on 10.55.0.0/24
Apr 13 18:49:48 toiler dhcpd: uid lease 10.55.0.217 for client 14:99:e2:27:0f:48 is duplicate on 10.55.0.0/24

Those events correspond nicely with the arp logs from above.

My concern is: why aren’t those log messages being communicated to me via logcheck?

I found the answer here:

$ cd /usr/local/etc/logcheck/ignore.d.server
$ grep dhcpd * | grep 'uid lease'
dhcp:^\w{3} [ :0-9]{11} [._[:alnum:]-]+ dhcpd: uid lease [.0-9]{7,15} for client [:[:xdigit:]]+ is duplicate on [.0-9]{7,15}/[[:digit:]]+$

It is explicitly ignored.

Looking at /var/db/dhcpd/dhcpd.leases I find:

lease 10.55.0.217 {
  starts 6 2014/04/12 18:56:40;
  ends 6 2014/04/12 19:21:44;
  tstp 6 2014/04/12 19:21:44;
  cltt 6 2014/04/12 18:56:40;
  binding state free;
  hardware ethernet 14:99:e2:27:0f:48;
  uid "\001\024\231\342'\017H";
}

Which is the Apple TV.

As shown above, dhcpd has been instructed to hand out a static IP (fixed-address Apple-TV.unixathome.org) for the Apple TV. So where does this lease entry come into play?

Talking out loud

Let me talk out loud about what I see. Please note: I have verified that the times on all servers are accurate.

19:38:56 bast kernel: arp: 10.55.0.62 moved from 78:ca:39:fe:d6:b3 to 14:99:e2:27:0f:48 on em0
19:38:58 toiler dhcpd: uid lease 10.55.0.217 for client 14:99:e2:27:0f:48 is duplicate on 10.55.0.0/24
19:39:35 bast kernel: arp: 10.55.0.62 moved from 14:99:e2:27:0f:48 to 78:ca:39:fe:d6:b3 on em0

Two seconds after arp notices that the Apple TV has 10.55.0.62, dhcpd mentions the duplicate lease for 10.55.0.217.

Trying pings

When I try to ping the Apple TV, I get:

$ ping -a 10.55.0.62
PING 10.55.0.62 (10.55.0.62): 56 data bytes
36 bytes from tardis.unixathome.org (10.55.0.63): Redirect Host(New addr: 10.55.0.62)
Vr HL TOS  Len   ID Flg  off TTL Pro  cks      Src      Dst
 4  5  00 0054 105b   0 0000  40  01 55a2 10.55.0.1  10.55.0.62 

36 bytes from tardis.unixathome.org (10.55.0.63): Redirect Host(New addr: 10.55.0.62)
Vr HL TOS  Len   ID Flg  off TTL Pro  cks      Src      Dst
 4  5  00 0054 105f   0 0000  40  01 559e 10.55.0.1  10.55.0.62 

36 bytes from tardis.unixathome.org (10.55.0.63): Redirect Host(New addr: 10.55.0.62)
Vr HL TOS  Len   ID Flg  off TTL Pro  cks      Src      Dst
 4  5  00 0054 1062   0 0000  40  01 559b 10.55.0.1  10.55.0.62 

^C
--- 10.55.0.62 ping statistics ---
3 packets transmitted, 0 packets received, 100.0% packet loss

tardis is my Apple Time Capsule, which also acts as a WAP. Note that when pinging 10.55.0.62 (the Apple TV), I get a reply from 10.55.0.62, and 10.55.0.1 is the host (my gateway) on which I was doing the ping.

If I ping from another host, I get similar results:

$ ping 10.55.0.52
PING 10.55.0.52 (10.55.0.52): 56 data bytes
ping: sendto: Host is down
^C
--- 10.55.0.52 ping statistics ---
6 packets transmitted, 0 packets received, 100.0% packet loss
$ 

I know the range handed out by dhcpd is 10.55.0.200 – 10.55.0.250.

Someone suggested there might be more than one dhcpd running. I installed net/dhcpdump in an attempt to learn more.

Running it, I found:

$ sudo dhcpdump -i em0
Password:
  TIME: 2014-04-13 20:28:07.775
    IP: 0.0.0.0 (14:99:e2:27:0f:48) > 255.255.255.255 (ff:ff:ff:ff:ff:ff)
    OP: 1 (BOOTPREQUEST)
 HTYPE: 1 (Ethernet)
  HLEN: 6
  HOPS: 0
   XID: 419223a9
  SECS: 1
 FLAGS: 0
CIADDR: 0.0.0.0
YIADDR: 0.0.0.0
SIADDR: 0.0.0.0
GIADDR: 0.0.0.0
CHADDR: 14:99:e2:27:0f:48:00:00:00:00:00:00:00:00:00:00
 SNAME: .
 FNAME: .
OPTION:  53 (  1) DHCP message type         3 (DHCPREQUEST)
OPTION:  55 (  6) Parameter Request List      1 (Subnet mask)
					      3 (Routers)
					      6 (DNS server)
					     15 (Domainname)
					    119 (Domain Search)
					    252 (MSFT - WinSock Proxy Auto Detect)
					    
OPTION:  57 (  2) Maximum DHCP message size 1500
OPTION:  61 (  7) Client-identifier         01:14:99:e2:27:0f:48
OPTION:  50 (  4) Request IP address        10.55.0.62
OPTION:  51 (  4) IP address leasetime      7776000 (12w6d)
OPTION:  12 (  8) Host name                 Apple-TV
---------------------------------------------------------------------------

This demonstrates that it is the Apple TV asking for a new IP address and it is getting 10.55.0.62.

I’m going to publish what I have so far and see where it leads.

Ideas

The ideas so far:

  • It’s the same device, connected via WIFI and wired
  • Check the devices for the MACs in question and figure out which is which

Wow!

Conall O’Brien just tweeted that this is the Bonjour Sleep Proxy.

My current proposed solution: instruct logcheck to ignore those entries in the log. Addenda (2014-04-14): This worked. Ignore it. It goes away. tm

Also suggested: net.link.ether.inet.log_arp_movements could be turned off to not log such movements.

Website Pin Facebook Twitter Myspace Friendfeed Technorati del.icio.us Digg Google StumbleUpon Premium Responsive