On Fri, Jul 22 2016, Guus Sliepen wrote: > On Thu, Jul 21, 2016 at 06:43:15PM -0700, Gerald Turner wrote: >> I have a Linux router running jessie that has four ethernet ports and >> a pair of ath9k radios. >> >> Three of the ethernet interfaces (eth0, eth1, eth2) are statically >> configured LAN ports. The fourth ethernet interface (eth3) is >> connected to an ISP via cable modem and uses DHCP¹. The two wlan >> interfaces are also configured statically and have hostapd running. > [...] >> My vague understanding is that wlan0/wlan1 don't have "carrier" until >> hostapd's take control. I believe this is what's causing ifupdown >> networking.service to timeout. > > Hm, I don't think that can be the problem. First, the carrier has > nothing to do with hotplugging. Hotplugging is when udev detects that > a device is added or removed. This should happen early at boot for > your radios. Second, you are doing static configuration of those > interfaces. That means ifupdown just executes the equivalent of the > ifconfig command. It doesn't wait for anything here. So this cannot > be the problem. Last, allow-hotplug interfaces are configured > asynchronously wrt. the normal boot process, so even if something > would hang here, it should not interfere with the boot process. > > If anything, ifupdown waits for dhclient on the eth3 interface to exit > before continuing. But according to your syslog it seems it got an IP > address just fine: > >> Jul 21 17:02:09 headboard ifup[2426]: DHCPREQUEST on eth3 to 255.255.255.255 >> port 67 >> Jul 21 17:02:09 headboard ifup[2426]: DHCPACK from 69.252.80.75 >> Jul 21 17:02:30 headboard systemd[1]: networking.service: Start operation >> timed out. Terminating. > > Maybe there is something in the backported ifupdown that doesn't > interact well with dhclient or something else from jessie. Could you > try removing "auto eth3" from /etc/network/interfaces and see if that > fixes the timeout? If that doesn't change anything, try removing the > "allow-hotplug" lines. That would at least narrow things down.
Yeah this is looking like a problem with ifupdown ↔ dhclient
interaction.
Removing "auto eth3" enabled networking.service to start without
timeout.
Using "allow-hotplug eth3" enabled networking.service to start without
timeout, however network-online.target is reached too soon, so the
brittle ordering of wide-dhcpv6-client and radvd is broken and various
services have to be manually restarted.
Also note that networking.service timesout during shutdown under any
condition ("auto eth3", "allow-hotplug eth3", or manual ifup after
boot), syslogs attached.
I noticed that the "DHCPACK from 69.252.80.75" doesn't match the address
in "DHCPRELEASE to 76.96.95.6", however examining /var/lib/dhcp/
dhclient.eth3.leases reveals that "option dhcp-server-identifier
76.96.95.6" so dhclient is probably just doing what it's told, however
bizarre (crazy ISP).
>> P.S. I noticed there's an /lib/systemd/system/ifup@.service file
>> installed by ifupdown, however I don't see it used anywhere, no
>> documentation, and only found a few meaningless results about it on
>> the www. Would it be sensible to disable networking.service and
>> enable ifup@eth0 et al services (perhaps with After=hostapd for
>> ifup@wlan0/1)?
>
> I wouldn't disable networking.service, instead don't mark those
> interfaces auto then.
Okay, I discovered how ifup@.service are wired (spawned by
ifupdown-hotplug).
On a tangent, now that I've taken Bob's suggestion to hook hostapd to
the allow-hotplug wlan's, I get proccesses contained like:
/
├─system.slice
│ ├─ifup@wlan1.service
│ │ └─2477 /usr/sbin/hostapd -B -P /run/hostapd.wlan1.pid
/etc/hostapd/hostapd-wlan1.conf
...but with either manual or "auto eth3" (with manual intervention after
the timeout), dhclient resides in a user session:
/
└─user.slice
└─user-1000.slice
├─user@1000.service
│ └─init.scope
│ ├─3660 /lib/systemd/systemd --user
│ └─3700 (sd-pam)
├─session-2.scope
│ └─4958 /sbin/dhclient -v -pf /run/dhclient.eth3.pid -lf
/var/lib/dhcp/dhclient.eth3.leases -I -df /var/lib/dhcp/dhclient6.eth3.leases
eth3
...which makes me wonder if dhclient would get by killed by systemd if I
hadn't already setup "loginctl enable-linger" on UID 1000.
--
Gerald Turner <gtur...@unzane.com> Encrypted mail preferred!
OpenPGP: 4096R / CA89 B27A 30FA 66C5 1B80 3858 EC94 2276 FDB8 716D
Jul 23 08:47:50 headboard systemd[1]: Stopped target Network is Online. Jul 23 08:47:50 headboard systemd[1]: Stopped target Network. Jul 23 08:47:50 headboard systemd[1]: Stopping ifup for wlan1... Jul 23 08:47:50 headboard systemd[1]: Stopping Raise network interfaces... Jul 23 08:47:50 headboard systemd[1]: Stopping ifup for wlan0... Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Stopped ifup for wlan1. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Stopped ifup for wlan0. Jul 23 08:47:50 headboard dhclient[4848]: Removed stale PID file Jul 23 08:47:50 headboard ifdown[4679]: Removed stale PID file Jul 23 08:47:50 headboard ifdown[4679]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 08:47:50 headboard ifdown[4679]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 08:47:50 headboard ifdown[4679]: All rights reserved. Jul 23 08:47:50 headboard ifdown[4679]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 08:47:50 headboard dhclient[4848]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 08:47:50 headboard dhclient[4848]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 08:47:50 headboard dhclient[4848]: All rights reserved. Jul 23 08:47:50 headboard dhclient[4848]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 08:47:50 headboard dhclient[4848]: Jul 23 08:47:50 headboard dhclient[4848]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Sending on Socket/fallback Jul 23 08:47:50 headboard dhclient[4848]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard dhclient[4848]: Sending on Socket/fallback Jul 23 08:47:50 headboard dhclient[4848]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 08:47:50 headboard ifdown[4679]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 08:47:54 headboard ntpd_intres[3356]: parent died before we finished, exiting Jul 23 08:47:54 headboard systemd-cryptsetup[4653]: Failed to deactivate: Device or resource busy Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Control process exited, code=exited status=1 Jul 23 08:47:54 headboard systemd[1]: Stopped Cryptography Setup for swap. Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Unit entered failed state. Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Failed with result 'exit-code'. Jul 23 08:47:54 headboard systemd[1]: Removed slice system-systemd\x2dcryptsetup.slice. Jul 23 08:47:54 headboard systemd[1]: Stopping Load/Save Random Seed... Jul 23 08:47:54 headboard systemd[1]: Stopped Load/Save Random Seed. Jul 23 08:48:20 headboard systemd[1]: networking.service: Stopping timed out. Terminating. Jul 23 08:48:20 headboard systemd[1]: Stopped Raise network interfaces. Jul 23 08:48:20 headboard systemd[1]: networking.service: Unit entered failed state. Jul 23 08:48:20 headboard systemd[1]: networking.service: Failed with result 'timeout'.
Jul 23 08:47:50 headboard systemd[1]: Stopped target Network is Online. Jul 23 08:47:50 headboard systemd[1]: Stopped target Network. Jul 23 08:47:50 headboard systemd[1]: Stopping ifup for wlan1... Jul 23 08:47:50 headboard systemd[1]: Stopping Raise network interfaces... Jul 23 08:47:50 headboard systemd[1]: Stopping ifup for wlan0... Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Stopped ifup for wlan1. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Reloading. Jul 23 08:47:50 headboard systemd[1]: Stopped ifup for wlan0. Jul 23 08:47:50 headboard dhclient[4848]: Removed stale PID file Jul 23 08:47:50 headboard ifdown[4679]: Removed stale PID file Jul 23 08:47:50 headboard ifdown[4679]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 08:47:50 headboard ifdown[4679]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 08:47:50 headboard ifdown[4679]: All rights reserved. Jul 23 08:47:50 headboard ifdown[4679]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 08:47:50 headboard dhclient[4848]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 08:47:50 headboard dhclient[4848]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 08:47:50 headboard dhclient[4848]: All rights reserved. Jul 23 08:47:50 headboard dhclient[4848]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 08:47:50 headboard dhclient[4848]: Jul 23 08:47:50 headboard dhclient[4848]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard ifdown[4679]: Sending on Socket/fallback Jul 23 08:47:50 headboard dhclient[4848]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 08:47:50 headboard dhclient[4848]: Sending on Socket/fallback Jul 23 08:47:50 headboard dhclient[4848]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 08:47:50 headboard ifdown[4679]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 08:47:54 headboard ntpd_intres[3356]: parent died before we finished, exiting Jul 23 08:47:54 headboard systemd-cryptsetup[4653]: Failed to deactivate: Device or resource busy Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Control process exited, code=exited status=1 Jul 23 08:47:54 headboard systemd[1]: Stopped Cryptography Setup for swap. Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Unit entered failed state. Jul 23 08:47:54 headboard systemd[1]: systemd-cryptsetup@swap.service: Failed with result 'exit-code'. Jul 23 08:47:54 headboard systemd[1]: Removed slice system-systemd\x2dcryptsetup.slice. Jul 23 08:47:54 headboard systemd[1]: Stopping Load/Save Random Seed... Jul 23 08:47:54 headboard systemd[1]: Stopped Load/Save Random Seed. Jul 23 08:48:20 headboard systemd[1]: networking.service: Stopping timed out. Terminating. Jul 23 08:48:20 headboard systemd[1]: Stopped Raise network interfaces. Jul 23 08:48:20 headboard systemd[1]: networking.service: Unit entered failed state. Jul 23 08:48:20 headboard systemd[1]: networking.service: Failed with result 'timeout'.
Jul 23 09:34:13 headboard systemd[1]: Stopped target Network is Online. Jul 23 09:34:13 headboard systemd[1]: Stopped target Network. Jul 23 09:34:13 headboard systemd[1]: Stopping ifup for wlan1... Jul 23 09:34:13 headboard systemd[1]: Stopping ifup for wlan0... Jul 23 09:34:13 headboard systemd[1]: Stopping Raise network interfaces... Jul 23 09:34:13 headboard systemd[1]: Stopping ifup for eth3... Jul 23 09:34:13 headboard systemd[1]: Reloading. Jul 23 09:34:13 headboard systemd[1]: Reloading. Jul 23 09:34:13 headboard systemd[1]: Reloading. Jul 23 09:34:13 headboard systemd[1]: Reloading. Jul 23 09:34:13 headboard dhclient[10430]: Killed old client process Jul 23 09:34:13 headboard ifdown[10242]: Killed old client process Jul 23 09:34:13 headboard systemd[1]: Reloading. Jul 23 09:34:14 headboard systemd[1]: Reloading. Jul 23 09:34:14 headboard systemd[1]: Stopped ifup for wlan1. Jul 23 09:34:14 headboard systemd[1]: Reloading. Jul 23 09:34:14 headboard systemd[1]: Stopped ifup for wlan0. Jul 23 09:34:14 headboard systemd[1]: Reloading. Jul 23 09:34:14 headboard systemd[1]: Reloading. Jul 23 09:34:14 headboard dhclient[10430]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 09:34:14 headboard ifdown[10242]: Internet Systems Consortium DHCP Client 4.3.1 Jul 23 09:34:14 headboard ifdown[10242]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 09:34:14 headboard ifdown[10242]: All rights reserved. Jul 23 09:34:14 headboard ifdown[10242]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 09:34:14 headboard dhclient[10430]: Copyright 2004-2014 Internet Systems Consortium. Jul 23 09:34:14 headboard dhclient[10430]: All rights reserved. Jul 23 09:34:14 headboard dhclient[10430]: For info, please visit https://www.isc.org/software/dhcp/ Jul 23 09:34:14 headboard dhclient[10430]: Jul 23 09:34:14 headboard dhclient[10430]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 09:34:14 headboard ifdown[10242]: Listening on LPF/eth3/00:25:90:aa:bb:cc Jul 23 09:34:14 headboard ifdown[10242]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 09:34:14 headboard ifdown[10242]: Sending on Socket/fallback Jul 23 09:34:14 headboard dhclient[10430]: Sending on LPF/eth3/00:25:90:aa:bb:cc Jul 23 09:34:14 headboard dhclient[10430]: Sending on Socket/fallback Jul 23 09:34:14 headboard dhclient[10430]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 09:34:14 headboard ifdown[10242]: DHCPRELEASE on eth3 to 76.96.95.6 port 67 Jul 23 09:34:15 headboard systemd[1]: Reloading. Jul 23 09:34:15 headboard systemd[1]: Reloading. Jul 23 09:34:16 headboard systemd[1]: Reloading. Jul 23 09:34:16 headboard systemd[1]: Reloading. Jul 23 09:34:16 headboard ifdown[10225]: /sbin/ifdown: waiting for lock on /run/network/ifstate.eth3 Jul 23 09:34:17 headboard systemd-cryptsetup[10187]: Failed to deactivate: Device or resource busy Jul 23 09:34:17 headboard systemd[1]: systemd-cryptsetup@swap.service: Control process exited, code=exited status=1 Jul 23 09:34:17 headboard systemd[1]: Stopped Cryptography Setup for swap. Jul 23 09:34:17 headboard systemd[1]: systemd-cryptsetup@swap.service: Unit entered failed state. Jul 23 09:34:17 headboard systemd[1]: systemd-cryptsetup@swap.service: Failed with result 'exit-code'. Jul 23 09:34:17 headboard systemd[1]: Removed slice system-systemd\x2dcryptsetup.slice. Jul 23 09:34:17 headboard systemd[1]: Stopping Load/Save Random Seed... Jul 23 09:34:17 headboard systemd[1]: Stopped Load/Save Random Seed. Jul 23 09:34:43 headboard systemd[1]: networking.service: Stopping timed out. Terminating. Jul 23 09:34:43 headboard systemd[1]: Stopped Raise network interfaces. Jul 23 09:34:43 headboard systemd[1]: networking.service: Unit entered failed state. Jul 23 09:34:43 headboard systemd[1]: networking.service: Failed with result 'timeout'. Jul 23 09:34:43 headboard systemd[1]: ifup@eth3.service: Stopping timed out. Terminating. Jul 23 09:34:43 headboard systemd[1]: Stopped ifup for eth3. Jul 23 09:34:43 headboard systemd[1]: ifup@eth3.service: Unit entered failed state. Jul 23 09:34:43 headboard systemd[1]: ifup@eth3.service: Failed with result 'timeout'.
signature.asc
Description: PGP signature
