dhcpcd-discuss

On Friday, October 17, 2014 5:16 PM, Roy Marples wrote:
> On 2014-10-18 01:07, David Hauck wrote:
>> On Friday, October 17, 2014 5:00 PM, Roy Marples wrote:
>>> On 2014-10-18 00:56, David Hauck wrote:
>>>>>> Add the word debug to dhcpcd.conf on a line by itself.
>>>>>> You may wish to remove your custom echo hook at this point :)
>>>>> 
>>>>> ;)
>>>> 
>>>> How do I get these debug statements in my syslog?
>>> 
>>> dhcpcd always outputs via syslog.
>>> The debug option just enables the mask to report syslog debug.
>> 
>> Right, I see this now ;). See below.
>> 
>>> Where it actually goes depends on your syslog config.
>>> By default on NetBSD for example, it goes nowhere (daemon debug
>>> isn't logged by default).
>>> On Linux metalog it ends up in /var/log/everything/current.
>> 
>> Here's the debug output:
> 
> Progress!
> 
>> 20141017 16:53:27.404 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' PREINIT 20141017 16:53:27.417 debug
>> daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' NOCARRIER
>> 20141017 16:53:29.096 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' CARRIER 20141017 16:53:29.110 debug
>> daemon(dhcpcd):eth1: delaying IPv4 for 0.8 seconds 20141017
>> 16:53:29.912 debug daemon(dhcpcd):eth1: sending DISCOVER (xid
>> 0xb788a71c), next in 3.8 seconds 20141017 16:53:33.681 debug
>> daemon(dhcpcd):eth1: sending DISCOVER (xid 0xb788a71c), next in 7.9
>> seconds 20141017 16:53:41.571 debug daemon(dhcpcd):eth1: sending
>> DISCOVER (xid 0xb788a71c), next in 15.3 seconds 20141017 16:53:49.918
>> debug daemon(dhcpcd):eth1: checking for 169.254.66.86 20141017
>> 16:53:49.918 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3),
>> next in 1.3 seconds 20141017 16:53:51.252 debug daemon(dhcpcd):eth1:
>> sending ARP probe (2 of 3), next in 1.5 seconds 20141017 16:53:52.707
>> debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0
>> seconds 20141017 16:53:54.709 debug daemon(dhcpcd):eth1: writing lease
>> `/var/db/dhcpcd-eth1.lease' 20141017 16:53:54.709 debug
>> daemon(dhcpcd):eth1: adding IP address 169.254.66.86/16 20141017
>> 16:53:54.709 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' IPV4LL 20141017 16:53:54.731 debug
>> daemon(dhcpcd):forking to background
> 
> Forked here
> 
>> 20141017 16:53:54.731 debug daemon(dhcpcd):eth1: sending ARP announce
>> (1 of 2), next in 2.0 seconds 20141017 16:53:56.731 debug
>> daemon(dhcpcd):eth1: sending ARP announce (2 of 2) 20141017
>> 16:54:09.906 debug daemon(dhcpcd):eth1: deleting IP address
>> 169.254.66.86/16 20141017 16:54:09.906 debug daemon(dhcpcd):eth1:
>> executing `/usr/lib/dhcpcd-run-hooks' STOP 20141017 16:54:09.923 debug
>> daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' STOPPED
> 
> dhcpcd *may* have exited here due to the down.
> Hard to say as you're not recording PIDs in the syslog.
> 
>> 20141017 16:54:39.544 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' PREINIT 20141017 16:54:39.553 debug
>> daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' NOCARRIER
>> 20141017 16:54:41.312 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' CARRIER 20141017 16:54:41.321 debug
>> daemon(dhcpcd):eth1: delaying IPv4 for 0.8 seconds 20141017
>> 16:54:42.174 debug daemon(dhcpcd):eth1: sending DISCOVER (xid
>> 0x65828a8c), next in 3.0 seconds 20141017 16:54:45.177 debug
>> daemon(dhcpcd):eth1: sending DISCOVER (xid 0x65828a8c), next in 7.8
>> seconds 20141017 16:54:53.026 debug daemon(dhcpcd):eth1: sending
>> DISCOVER (xid 0x65828a8c), next in 16.9 seconds 20141017 16:55:02.180
>> debug daemon(dhcpcd):eth1: checking for 169.254.24.210 20141017
>> 16:55:02.180 debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3),
>> next in 2.0 seconds 20141017 16:55:04.162 debug daemon(dhcpcd):eth1:
>> sending ARP probe (2 of 3), next in 1.6 seconds 20141017 16:55:05.806
>> debug daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0
>> seconds 20141017 16:55:07.809 debug daemon(dhcpcd):eth1: writing lease
>> `/var/db/dhcpcd-eth1.lease' 20141017 16:55:07.809 debug
>> daemon(dhcpcd):eth1: adding IP address 169.254.24.210/16 20141017
>> 16:55:07.809 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' IPV4LL 20141017 16:55:07.821 debug
>> daemon(dhcpcd):forking to background
> 
> Forked again here.
> If dhcpcd exited earlier, all is good. If not, bad.
> Probably bad as no message about dhcpcd starting.
> 
>> 20141017 16:55:07.821 debug daemon(dhcpcd):eth1: sending ARP announce
>> (1 of 2), next in 2.0 seconds 20141017 16:55:09.823 debug
>> daemon(dhcpcd):eth1: sending ARP announce (2 of 2) 20141017
>> 16:56:15.555 debug daemon(dhcpcd):eth1: sending DISCOVER (xid
>> 0xb6bdf9d4), next in 64.4 seconds 20141017 16:56:54.544 debug
>> daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' NOCARRIER
>> 20141017 16:56:54.562 debug daemon(dhcpcd):eth1: deleting IP address
>> 169.254.24.210/16 20141017 16:56:54.562 debug daemon(dhcpcd):eth1:
>> executing `/usr/lib/dhcpcd-run-hooks' EXPIRE 20141017 16:57:01.325
>> debug daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks'
>> CARRIER 20141017 16:57:01.334 debug daemon(dhcpcd):eth1: delaying IPv4
>> for 0.2 seconds 20141017 16:57:01.526 debug daemon(dhcpcd):eth1:
>> reading lease `/var/db/dhcpcd-eth1.lease' 20141017 16:57:01.531 debug
>> daemon(dhcpcd):eth1: checking for 169.254.24.210 20141017 16:57:01.532
>> debug daemon(dhcpcd):eth1: sending ARP probe (1 of 3), next in 1.7
>> seconds 20141017 16:57:03.198 debug daemon(dhcpcd):eth1: sending ARP
>> probe (2 of 3), next in 1.7 seconds 20141017 16:57:04.877 debug
>> daemon(dhcpcd):eth1: sending ARP probe (3 of 3), next in 2.0 seconds
>> 20141017 16:57:06.879 debug daemon(dhcpcd):eth1: writing lease
>> `/var/db/dhcpcd-eth1.lease' 20141017 16:57:06.880 debug
>> daemon(dhcpcd):eth1: adding IP address 169.254.24.210/16 20141017
>> 16:57:06.880 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' IPV4LL 20141017 16:57:06.891 debug
>> daemon(dhcpcd):eth1: sending ARP announce (1 of 2), next in 2.0 seconds
>> 20141017 16:57:06.891 debug daemon(dhcpcd):eth1: defended IPv4LL
>> address 20141017 16:57:08.893 debug daemon(dhcpcd):eth1: sending ARP
>> announce (2 of 2) 20141017 16:57:08.903 debug daemon(dhcpcd):eth1:
>> deleting IP address 169.254.24.210/16 20141017 16:57:08.903 debug
>> daemon(dhcpcd):eth1: executing `/usr/lib/dhcpcd-run-hooks' EXPIRE
> 
> So that's the reason maybe? Defending the IPv4LL address triggered an
> expiry? I may have to setup a reverse ARP proxy to test this.
> 
>> 20141017 16:57:09.917 debug daemon(dhcpcd):eth1: checking for
>> 169.254.110.19
>> 20141017 16:57:09.918 debug daemon(dhcpcd):eth1: sending ARP probe
>> (1 of 3), next in 1.6 seconds
>> 20141017 16:57:11.478 debug daemon(dhcpcd):eth1: sending ARP probe
>> (2 of 3), next in 1.8 seconds
>> 20141017 16:57:13.298 debug daemon(dhcpcd):eth1: sending ARP probe
>> (3 of 3), next in 2.0 seconds
>> 20141017 16:57:15.300 debug daemon(dhcpcd):eth1: executing
>> `/usr/lib/dhcpcd-run-hooks' EXPIRE
> 
> Looks like a bug here, maybe triggered by the above.
> 
> Something to look into next week.

OK, no problem. Glad I was finally able to get you something that you can chew on ;). Enjoy the weekend!

> Roy