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

_______________________________________________
networkmanager-list mailing list
[email protected]
https://mail.gnome.org/mailman/listinfo/networkmanager-list

Reply via email to