On Tue, 2018-06-05 at 14:25 +0200, Thomas Haller wrote:
nm-online in "--wait-for-startup" mode is very different from the regular mode (as the manual page explains).
Which I don't seem to ever get.
If you enable level=TRACE logging (see [1]), you will also see messages: manager: check_if_startup_complete returns FALSE because of eth0 which tells you reasons why NM thinks startup is not completed yet.
I get: Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8512] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5051] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5303] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5464] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5668] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5840] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5843] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5846] manager: check_if_startup_complete returns FALSE because of enp2s0 Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5848] manager: check_if_startup_complete returns FALSE because of enp2s0
If you dig further, search for "pending.action" messages: (eth0): add_pending_action (1): 'carrier-wait' (eth0): remove_pending_action (0): 'carrier-wait' As long as there are such pending actions on a device, startup- complete won't be reached either. Pending-actions are not the only reason for blocking startup-complete, but a common one.
The pending actions from my last startup: Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.5427] device[0x55d7468810e0] (enp2s0): add_pending_action (1): 'carrier-wait' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181595.5427] device[0x55d7468810e0] (enp2s0): remove_pending_action (1): 'dhcp6' not pending (expected) Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181595.5428] device[0x55d7468810e0] (enp2s0): remove_pending_action (1): 'autoconf6' not pending (expected) Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8116] device[0x55d746897e80] (pc_bridge): add_pending_action (1): 'carrier-wait' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181595.8116] device[0x55d746897e80] (pc_bridge): remove_pending_action (1): 'dhcp6' not pending (expected) Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181595.8116] device[0x55d746897e80] (pc_bridge): remove_pending_action (1): 'autoconf6' not pending (expected) Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8125] device[0x55d746897e80] (pc_bridge): add_pending_action (2): 'recheck-available' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8151] device[0x55d746897e80] (pc_bridge): add_pending_action (3): 'queued-state-change-disconnected' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8152] device[0x55d746897e80] (pc_bridge): remove_pending_action (2): 'recheck-available' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8270] device[0x55d746897e80] (pc_bridge): add_pending_action (3): 'autoactivate' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8270] device[0x55d746897e80] (pc_bridge): remove_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8307] device[0x55d746897e80] (pc_bridge): add_pending_action (3): 'activation-0x55d7468929c0' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181595.8312] device[0x55d746897e80] (pc_bridge): remove_pending_action (2): 'autoactivate' Jun 28 06:26:35 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181595.8498] device[0x55d746897e80] (pc_bridge): add_pending_action (2): 'carrier-wait' already pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5044] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5044] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5051] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): add_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5284] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5284] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5302] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): add_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5461] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5461] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5464] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): add_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5664] device[0x55d746917020] (BC:F5:AC:81:19:68): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181596.5664] device[0x55d746917020] (BC:F5:AC:81:19:68): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5668] device[0x55d746917020] (BC:F5:AC:81:19:68): add_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5770] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): add_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5770] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): remove_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5773] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): add_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5773] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): remove_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5776] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): add_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5776] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): remove_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5778] device[0x55d746917020] (BC:F5:AC:81:19:68): add_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5778] device[0x55d746917020] (BC:F5:AC:81:19:68): remove_pending_action (1): 'recheck-available' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5782] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): add_pending_action (2): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5782] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): remove_pending_action (1): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5785] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): add_pending_action (2): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5785] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): remove_pending_action (1): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5788] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): add_pending_action (2): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5788] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): remove_pending_action (1): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5791] device[0x55d746917020] (BC:F5:AC:81:19:68): add_pending_action (2): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5792] device[0x55d746917020] (BC:F5:AC:81:19:68): remove_pending_action (1): 'queued-state-change-disconnected' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5839] device[0x55d7468f0050] (14:F4:2A:02:DA:AD): remove_pending_action (0): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5842] device[0x55d7468fc2d0] (58:3F:54:3F:FC:CD): remove_pending_action (0): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5845] device[0x55d74690cda0] (BC:F5:AC:33:CA:C1): remove_pending_action (0): 'autoactivate' Jun 28 06:26:36 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181596.5848] device[0x55d746917020] (BC:F5:AC:81:19:68): remove_pending_action (0): 'autoactivate' Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9974] device[0x55d7468810e0] (enp2s0): add_pending_action (2): 'queued-state-change-disconnected' Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9975] device[0x55d7468810e0] (enp2s0): remove_pending_action (1): 'carrier-wait' Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9993] device[0x55d7468810e0] (enp2s0): add_pending_action (2): 'autoactivate' Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9993] device[0x55d7468810e0] (enp2s0): remove_pending_action (1): 'queued-state-change-disconnected' Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9997] device[0x55d7468810e0] (enp2s0): add_pending_action (2): 'activation-0x55d746892f60' Jun 28 06:26:38 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181598.0001] device[0x55d7468810e0] (enp2s0): remove_pending_action (1): 'autoactivate' Jun 28 06:28:43 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181723.1681] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:28:43 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181723.1681] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:30:31 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181831.8620] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:30:31 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530181831.8620] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:33:56 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182036.8020] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:33:56 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182036.8020] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:38:12 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182292.0032] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:38:12 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182292.0032] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:41:54 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182514.2826] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:41:54 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182514.2826] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:42:52 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182572.4175] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:42:52 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182572.4176] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:43:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182616.5113] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:43:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530182616.5114] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:50:51 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183051.5627] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:50:51 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183051.5627] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:53:56 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183236.7620] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:53:56 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183236.7620] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 06:58:19 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183499.4859] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 06:58:19 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183499.4861] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:01:29 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183689.7212] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:01:29 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183689.7213] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:05:09 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183909.5353] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:05:09 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183909.5355] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:05:32 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183932.2709] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:05:32 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530183932.2710] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:13:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184416.5618] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:13:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184416.5619] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:14:14 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184454.3924] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:14:14 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184454.3924] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:17:59 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184679.9942] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:17:59 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184679.9942] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:21:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184896.3460] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:21:36 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184896.3460] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:22:57 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184977.4827] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:22:57 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530184977.4827] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) Jun 28 07:26:19 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530185179.6143] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'dhcp6' not pending (expected) Jun 28 07:26:19 pc.interlinx.bc.ca NetworkManager[1415]: <trace> [1530185179.6143] device[0x55d7468810e0] (enp2s0): remove_pending_action (0): 'autoconf6' not pending (expected) It looks like: Jun 28 06:26:37 pc.interlinx.bc.ca NetworkManager[1415]: <debug> [1530181597.9997] device[0x55d7468810e0] (enp2s0): add_pending_action (2): 'activation-0x55d746892f60' doesn't have it's pending action removed. I'm not sure what that was is meaning though. Cheers, b.
Attachment:
signature.asc
Description: This is a digitally signed message part