RE: IPV4LL and EXPIRE
Roy Marples
Sat Oct 18 00:16:27 2014
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.
Roy
Archive administrator: postmaster@marples.name