dhcpcd-discuss

Re: dhcpcd 7.1.1 (and 7.2.0) time out on boot

Matt Horan

Thu Apr 25 16:22:49 2019

On Thu, Apr 25, 2019 at 03:47:45PM +0100, Roy Marples wrote:
> On 25/04/2019 15:16, Matt Horan wrote:
> >> Does dhcpcd recover from carrier loss?
> > 
> > It doesn't seem so. After the first reboot I waited over a minute and
> > dhcpcd never got a lease. When I restarted dhcpcd it got a lease
> > immediately.
> > 
> > I do see that dhcpcd forks to the background, so it should still be
> > running, but seems to not detect that carrier has returned. IPv4 works
> > fine during the entire process, so I believe the interface is still up.
> 
> OK.
> 
> Can you add this to the top of dhcpcd.conf please?
> 
> debug
> logfile /var/log/dhcpcd.log
> 
> Reboot and then email me the log - privately if you feel it has 
> sensitive data.

dhcpcd.log and dmesg with route monitor output attached.

-- 
Matt Horan matt@xxxxxxxxxxxxx https://matthoran.com/
Apr 25 11:13:36 [65404]: dhcpcd-7.1.1 starting
Apr 25 11:13:36 [65404]: DUID 00:01:00:01:24:53:c3:07:00:0d:b9:41:d8:74
Apr 25 11:13:36 [65404]: em0: IAID b9:41:d8:74
Apr 25 11:13:36 [65404]: em0: IA type 25 IAID 00:00:00:00
Apr 25 11:13:36 [65404]: em0: delaying IPv6 router solicitation for 1.0 seconds
Apr 25 11:13:36 [65404]: em0: reading lease `/var/db/dhcpcd/em0.lease6'
Apr 25 11:13:36 [65404]: em0: rebinding prior DHCPv6 lease
Apr 25 11:13:36 [65404]: em0: delaying REBIND6 (xid 0x8b4976), next in 0.9 seconds
Apr 25 11:13:36 [65404]: em1: IAID b9:41:d8:75
Apr 25 11:13:36 [65404]: em0: carrier lost
Apr 25 11:14:06 [65404]: timed out
Apr 25 11:14:06 [65404]: forking to background
Apr 25 11:14:06 [65404]: forked to background, child pid 29918
starting package daemons: dhcpcdgot message of size 168 on Thu Apr 25 11:13:36 2019
RTM_IFINFO: iface status change: len 168, if# 1, name: em0, link: active, mtu: 1500, flags:<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST>
got message of size 192 on Thu Apr 25 11:13:36 2019
RTM_GET: Report Metrics: len 192, priority 8, table 0, ifidx 1, pid: 39731, seq 2128284594, errno 0
flags:<UP,GATEWAY,DONE,STATIC>
fmask:
use:     4089   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA>
 0.0.0.0 24.193.94.1 0.0.0.0 00:0d:b9:41:d8:74 24.193.94.231
got message of size 120 on Thu Apr 25 11:13:36 2019
RTM_NEWADDR: address being added to iface: len 120, metric 0, flags:
sockaddrs: <NETMASK,IFP,IFA>
 ffff:ffff:ffff:ffff:: 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
got message of size 224 on Thu Apr 25 11:13:36 2019
RTM_ADD: Add Route: len 224, priority 1, table 0, ifidx 2, pid: 0, seq 0, errno 0
flags:<UP,HOST,DONE,LLINFO,LOCAL>
fmask:
use:        0   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,IFP,IFA>
 fe80::826f:f28a:bbae:c448%em1 00:0d:b9:41:d8:75 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
got message of size 256 on Thu Apr 25 11:13:36 2019
RTM_ADD: Add Route: len 256, priority 4, table 0, ifidx 2, pid: 0, seq 0, errno 0
flags:<UP,DONE,CLONING,CONNECTED>
fmask:
use:        0   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA>
 fe80::%em1 fe80::826f:f28a:bbae:c448%em1 ffff:ffff:ffff:ffff:: 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
got message of size 296 on Thu Apr 25 11:13:36 2019
RTM_DELETE: Delete Route: len 296, priority 56, table 0, ifidx 1, pid: 21594, seq 2, errno 0
flags:<GATEWAY,DONE,STATIC>
fmask:
use:        8   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,NETMASK,IFP,IFA,LABEL>
 :: fe80::217:10ff:fe88:8be1%em0 :: 00:0d:b9:41:d8:74 fe80::e399:de83:d65:ac4c%em0 "slaacd"
got message of size 192 on Thu Apr 25 11:13:37 2019
RTM_CHGADDRATTR: address attributes being changed: len 192, metric 0, flags:
sockaddrs: <NETMASK,IFP,IFA>
 ffff:ffff:ffff:ffff:: 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
got message of size 224 on Thu Apr 25 11:13:39 2019
RTM_ADD: Add Route: len 224, priority 3, table 0, ifidx 2, pid: 0, seq 0, errno 0
flags:<UP,HOST,DONE,LLINFO,CLONED>
fmask:
use:        0   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,IFP,IFA>
 fe80::4e34:88ff:fe8c:6c75%em1 link#2 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
got message of size 224 on Thu Apr 25 11:13:39 2019
RTM_RESOLVE: Route created by cloning: len 224, priority 3, table 0, ifidx 2, pid: 0, seq 0, errno 0
flags:<UP,HOST,DONE,LLINFO,CLONED>
fmask:
use:        0   mtu:        0    expire:        0 
locks:  inits: 
sockaddrs: <DST,GATEWAY,IFP,IFA>
 fe80::4e34:88ff:fe8c:6c75%em1 4c:34:88:8c:6c:75 00:0d:b9:41:d8:75 fe80::826f:f28a:bbae:c448%em1
.

Follow-Ups:
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootMatt Horan
References:
dhcpcd 7.1.1 (and 7.2.0) time out on bootMatt Horan
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootMatt Horan
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootRoy Marples
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootMatt Horan
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootRoy Marples
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootMatt Horan
Re: dhcpcd 7.1.1 (and 7.2.0) time out on bootRoy Marples
Archive administrator: postmaster@marples.name