dhclient SYNCDHCP messiness

[Ian Lepore]

On Wed, 2012-02-22 at 14:08 -0700, Warren Block wrote:
> On Wed, 22 Feb 2012, Ian Lepore wrote:
> 
> > On Wed, 2012-02-22 at 11:40 -0700, Warren Block wrote:
> >> In /etc/rc.conf:
> >>
> >>    ifconfig_em0="SYNCDHCP"
> >>
> >> dhclient runs on startup, then later tries to run again:
> >>
> >>    Starting dhclient.
> >>    em0: no link ...
> >>    .
> >>    .
> >>    got link
> >>    (...)
> >>    Starting Network: lo0 em0.
> >>    (...)
> >>    Starting devd.
> >>    Starting ums0 moused
> >>    .
> >>    dhclient already running? (pid=344).
> >>    Creating and/or trimming log files
> >>
> >> So is this from /etc/network.subr starting dhclient because the
> >> interface is set to DHCP, then /etc/rc.d/dhclient running directly
> >> later?
> >>
> >> This is with
> >>
> >> FreeBSD lightning 8.3-PRERELEASE FreeBSD 8.3-PRERELEASE #0: Tue Feb 21 22:25:30 MST 2012
> >> root at lightning:/usr/obj/usr/src/sys/LIGHTNING  i386
> >
> > From the sequence of things there it looks like the second invocation
> > may be from a devd rule, but I thought all the standard rules used
> > "dhclient quietstart" and that one of the effects of that was to supress
> > the "already running" warning.
> 
> The devd rule triggers on a link up event.  This is an em(4) card that 
> does not do the multiple up/down events on start like an re(4) card. 
> But easy to test.  ...And interestingly enough, commenting out lines 
> 51-56 of devd.conf stops the double call:
> 
>    DHCPREQUEST on em0 to 255.255.255.255 port 67
>    DHCPACK from 10.0.0.1
>    bound to 10.0.0.8 -- renewal in 300 seconds.
>    Starting Network: lo0 em0.
>    lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
>            options=3<RXCSUM,TXCSUM>
>            inet 127.0.0.1 netmask 0xff000000
>    em0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 9216
>            options=9b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM>
>            ether 00:02:b3:a9:93:d7
>            inet 10.0.0.8 netmask 0xffffff00 broadcast 10.0.0.255
>            media: Ethernet autoselect (1000baseT <full-duplex>)
>            status: active
>    Starting devd.
>    Starting ums0 moused
>    .
>    Creating and/or trimming log files
> 
> For completeness, there's an unconnected re(4) card built into the 
> motherboard that shows "re0: link state changed to DOWN" immediately 
> after the "Starting devd." message.
> 
> AFAIK, it should happen like this:
> 
> ifconfig em0
> em0 changes to up
> dhclient em0 (sync)
> wait until em0 gets a DHCP lease or fails
> devd (em0 is already up, devd should do nothing)
> 
> So I guess the question is: why is devd seeing a link up event there?
> 
> > I updated a couple systems to 8.3-{PRERELEASE,BETA1} over the past few
> > days and I haven't seen such a glitch.  I don't think it should make a
> > difference, but I use synchronous_dhclient=YES and ifconfig_foo=DHCP
> 
> That's a good point: testing... nope, it does the same thing as 
> "SYNCDHCP".
> 
> 

First, let me correct myself:  I *am* seeing exactly this glitch, I just
hadn't noticed it until a few minutes ago when I rebooted and looked
much more closely.

Devd sees the link-up event because it sees all the events that happened
before it started (for some definition of "all"; there's probably some
reasonable list-length or buffer size limit somewhere).  I rebooted to
test my vague memory on this... boot into single-user mode and manually
run /sbin/devd -D and you'll see it processing the buffered events
before daemonizing.  For some reason I had to mount / writeable before
running devd in single-user or it failed.

I now suspect (but haven't tested to confirm) that this message may be a
side effect of r226345 which replaced some one-off pidfile logic in
rc.d/dhclient with use of the standard rc_pid scheme, which is what is
doing the whining.  I think the old one-off code to deal with the
pidfile avoided whining in the 'quietstart' case.

-- Ian