NM fails with 'config-failed' despite successful MM connection
Dan Williams
dcbw at redhat.com
Wed Jan 4 16:21:46 UTC 2017
On Wed, 2017-01-04 at 16:12 +0100, Bjørn Mork wrote:
> lately I've been having some problems connecting, using the EM7455 in
> my
> laptop. Connections often fail like this:
>
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.5964] device (cdc-wdm0): Activation: starting
> connection 'Telenor ("telenor.smart")' (3fdb56ec-485a-485c-9b05-
> d9e80a5aa52f)
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.5965] audit: op="connection-activate"
> uuid="3fdb56ec-485a-485c-9b05-d9e80a5aa52f" name="Telenor
> ("telenor.smart")" pid=3985 uid=1000 result="success"
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.5967] device (cdc-wdm0): state change:
> disconnected -> prepare (reason 'none') [30 40 0]
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.8935] device (cdc-wdm0): state change: prepare ->
> config (reason 'none') [40 50 0]
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.8965] device (cdc-wdm0): state change: config ->
> failed (reason 'config-failed') [50 120 4]
> Jan 4 15:58:01 miraculix kernel: [93879.513158] IPv6:
> ADDRCONF(NETDEV_UP): wwan0: link is not ready
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <warn> [1483541881.9013] device (cdc-wdm0): Activation: failed for
> connection 'Telenor ("telenor.smart")'
> Jan 4 15:58:01 miraculix NetworkManager[513]:
> <info> [1483541881.9047] device (cdc-wdm0): state change: failed ->
> disconnected (reason 'none') [120 30 0]
Could you:
nmcli g log level debug
and grab a trace when NM fails to configure? That'll tell us what's
happening on the NM side.
Dan
>
> Repeated attemtps will eventually succeed, but this starting to be
> annoying for me to run ModemManager in debug mode. And what I see
> there, is this:
>
> ModemManager[5730]: <debug> [1483541881.740977] [mm-broadband-modem-
> mbim.c:2252] device_notification_cb(): Received notification (service
> 'basic-connect', command 'connect')
> ModemManager[5730]: [/dev/cdc-wdm0] Received message...
> > > > > > > RAW:
> > > > > > > length = 84
> > > > > > > data =
> > > > > > > 03:00:00:80:54:00:00:00:21:00:00:00:01:00:00:00:00:00:00:
> > > > > > > 00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:
> > > > > > > 00:00:00:00:00:00:24:00:00:00:00:00:00:00:01:00:00:00:00:
> > > > > > > 00:00:00:03:00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:
> > > > > > > 7E:5E:2A:7E:00:00:00:00
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message (translated)...
> > > > > > > Header:
> > > > > > > length = 84
> > > > > > > type = command-done (0x80000003)
> > > > > > > transaction = 33
> > > > > > > Fragment header:
> > > > > > > total = 1
> > > > > > > current = 0
> > > > > > > Contents:
> > > > > > > status error = 'None' (0x00000000)
> > > > > > > service = 'basic-connect' (a289cc33-bcbb-8b4f-
> > > > > > > b6b0-133ec2aae6df)
> > > > > > > cid = 'connect' (0x0000000c)
>
> ModemManager[5730]: <debug> [1483541881.805480] [mm-bearer-
> mbim.c:614] connect_set_ready(): Session ID '0': activated (IP type:
> ipv4v6)
> ModemManager[5730]: <debug> [1483541881.805626] [mm-bearer-
> mbim.c:932] connect_context_step(): Querying IP configuration...
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message...
> <<<<<< RAW:
> <<<<<< length = 108
> <<<<<< data =
> 03:00:00:00:6C:00:00:00:22:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:
> 33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0F:00:00:00:00:00:00:00:3C:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message (translated)...
> <<<<<< Header:
> <<<<<< length = 108
> <<<<<< type = command (0x00000003)
> <<<<<< transaction = 34
> <<<<<< Fragment header:
> <<<<<< total = 1
> <<<<<< current = 0
> <<<<<< Contents:
> <<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-
> 133ec2aae6df)
> <<<<<< cid = 'ip-configuration' (0x0000000f)
> <<<<<< type = 'query' (0x00000000)
> ModemManager[5730]: [/dev/cdc-wdm0] Received message...
> > > > > > > RAW:
> > > > > > > length = 196
> > > > > > > data =
> > > > > > > 03:00:00:80:C4:00:00:00:22:00:00:00:01:00:00:00:00:00:00:
> > > > > > > 00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0F:00:
> > > > > > > 00:00:00:00:00:00:94:00:00:00:00:00:00:00:0F:00:00:00:0F:
> > > > > > > 00:00:00:01:00:00:00:3C:00:00:00:01:00:00:00:50:00:00:00:
> > > > > > > 44:00:00:00:64:00:00:00:02:00:00:00:48:00:00:00:02:00:00:
> > > > > > > 00:74:00:00:00:DC:05:00:00:DC:05:00:00:1E:00:00:00:0A:97:
> > > > > > > 86:DE:0A:97:86:DD:C1:D5:70:04:82:43:0F:C6:40:00:00:00:2A:
> > > > > > > 02:21:21:02:4A:2B:9E:BC:2E:A5:47:2B:4F:B0:1D:2A:02:21:21:
> > > > > > > 02:4A:2B:9E:D9:E9:90:E3:C4:B7:17:EB:20:01:46:00:00:04:0F:
> > > > > > > FF:00:00:00:00:00:00:00:52:20:01:46:00:00:04:1F:FF:00:00:
> > > > > > > 00:00:00:00:00:52
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message (translated)...
> > > > > > > Header:
> > > > > > > length = 196
> > > > > > > type = command-done (0x80000003)
> > > > > > > transaction = 34
> > > > > > > Fragment header:
> > > > > > > total = 1
> > > > > > > current = 0
> > > > > > > Contents:
> > > > > > > status error = 'None' (0x00000000)
> > > > > > > service = 'basic-connect' (a289cc33-bcbb-8b4f-
> > > > > > > b6b0-133ec2aae6df)
> > > > > > > cid = 'ip-configuration' (0x0000000f)
>
> ModemManager[5730]: <debug> [1483541881.869422] [mm-bearer-
> mbim.c:319] ip_configuration_query_ready(): IPv4 configuration
> available: 'address, gateway, dns, mtu'
> ModemManager[5730]: <debug> [1483541881.869556] [mm-bearer-
> mbim.c:325] ip_configuration_query_ready(): IP addresses (1)
> ModemManager[5730]: <debug> [1483541881.870082] [mm-bearer-
> mbim.c:329] ip_configuration_query_ready(): IP [0]:
> '10.151.134.222/30'
> ModemManager[5730]: <debug> [1483541881.870252] [mm-bearer-
> mbim.c:338] ip_configuration_query_ready(): Gateway:
> '10.151.134.221'
> ModemManager[5730]: <debug> [1483541881.870374] [mm-bearer-
> mbim.c:346] ip_configuration_query_ready(): DNS addresses (2)
> ModemManager[5730]: <debug> [1483541881.870515] [mm-bearer-
> mbim.c:351] ip_configuration_query_ready(): DNS [0]:
> '193.213.112.4'
> ModemManager[5730]: <debug> [1483541881.870627] [mm-bearer-
> mbim.c:351] ip_configuration_query_ready(): DNS [1]:
> '130.67.15.198'
> ModemManager[5730]: <debug> [1483541881.870837] [mm-bearer-
> mbim.c:359] ip_configuration_query_ready(): MTU: '1500'
> ModemManager[5730]: <debug> [1483541881.870968] [mm-bearer-
> mbim.c:365] ip_configuration_query_ready(): IPv6 configuration
> available: 'address, gateway, dns, mtu'
> ModemManager[5730]: <debug> [1483541881.871077] [mm-bearer-
> mbim.c:371] ip_configuration_query_ready(): IP addresses (1)
> ModemManager[5730]: <debug> [1483541881.871220] [mm-bearer-
> mbim.c:375] ip_configuration_query_ready(): IP [0]:
> '2a02:2121:24a:2b9e:bc2e:a547:2b4f:b01d/64'
> ModemManager[5730]: <debug> [1483541881.871404] [mm-bearer-
> mbim.c:384] ip_configuration_query_ready(): Gateway:
> '2a02:2121:24a:2b9e:d9e9:90e3:c4b7:17eb'
> ModemManager[5730]: <debug> [1483541881.871497] [mm-bearer-
> mbim.c:392] ip_configuration_query_ready(): DNS addresses (2)
> ModemManager[5730]: <debug> [1483541881.871749] [mm-bearer-
> mbim.c:397] ip_configuration_query_ready(): DNS [0]:
> '2001:4600:4:fff::52'
> ModemManager[5730]: <debug> [1483541881.871940] [mm-bearer-
> mbim.c:397] ip_configuration_query_ready(): DNS [1]:
> '2001:4600:4:1fff::52'
> ModemManager[5730]: <debug> [1483541881.872065] [mm-bearer-
> mbim.c:405] ip_configuration_query_ready(): MTU: '1500'
> ModemManager[5730]: <debug> [1483541881.872461] [mm-port.c:94]
> mm_port_set_connected(): (wwan0): port now connected
> ModemManager[5730]: <debug> [1483541881.872722] [mm-base-
> bearer.c:699] connect_ready(): Connected bearer
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message...
> <<<<<< RAW:
> <<<<<< length = 48
> <<<<<< data =
> 03:00:00:00:30:00:00:00:23:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:
> 33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:14:00:00:00:00:00:00:00:00:00:
> 00:00
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message (translated)...
> <<<<<< Header:
> <<<<<< length = 48
> <<<<<< type = command (0x00000003)
> <<<<<< transaction = 35
> <<<<<< Fragment header:
> <<<<<< total = 1
> <<<<<< current = 0
> <<<<<< Contents:
> <<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-
> 133ec2aae6df)
> <<<<<< cid = 'packet-statistics' (0x00000014)
> <<<<<< type = 'query' (0x00000000)
> ModemManager[5730]: <info> [1483541881.874089] [mm-iface-
> modem.c:1431] __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> connected)
> ModemManager[5730]: <info> [1483541881.875422] [mm-iface-modem-
> simple.c:602] connection_step(): Simple connect state (8/8): All done
> ModemManager[5730]: <debug> [1483541881.923420] [mm-base-
> bearer.c:972] mm_base_bearer_disconnect(): Disconnecting bearer
> '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[5730]: <info> [1483541881.923523] [mm-iface-
> modem.c:1431] __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
> disconnecting)
> ModemManager[5730]: <debug> [1483541881.924140] [mm-bearer-
> mbim.c:1238] disconnect(): Launching disconnection on data port
> (net/wwan0)
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message...
> <<<<<< RAW:
> <<<<<< length = 108
> <<<<<< data =
> 03:00:00:00:6C:00:00:00:24:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:
> 33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:00:00:01:00:00:00:3C:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> 7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E
> ModemManager[5730]: [/dev/cdc-wdm0] Sent message (translated)...
> <<<<<< Header:
> <<<<<< length = 108
> <<<<<< type = command (0x00000003)
> <<<<<< transaction = 36
> <<<<<< Fragment header:
> <<<<<< total = 1
> <<<<<< current = 0
> <<<<<< Contents:
> <<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-
> 133ec2aae6df)
> <<<<<< cid = 'connect' (0x0000000c)
> <<<<<< type = 'set' (0x00000001)
> ModemManager[5730]: [/dev/cdc-wdm0] Received message...
> > > > > > > RAW:
> > > > > > > length = 96
> > > > > > > data =
> > > > > > > 03:00:00:80:60:00:00:00:23:00:00:00:01:00:00:00:00:00:00:
> > > > > > > 00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:14:00:
> > > > > > > 00:00:00:00:00:00:30:00:00:00:00:00:00:00:00:00:00:00:00:
> > > > > > > 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> > > > > > > 00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:
> > > > > > > 00
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message (translated)...
> > > > > > > Header:
> > > > > > > length = 96
> > > > > > > type = command-done (0x80000003)
> > > > > > > transaction = 35
> > > > > > > Fragment header:
> > > > > > > total = 1
> > > > > > > current = 0
> > > > > > > Contents:
> > > > > > > status error = 'None' (0x00000000)
> > > > > > > service = 'basic-connect' (a289cc33-bcbb-8b4f-
> > > > > > > b6b0-133ec2aae6df)
> > > > > > > cid = 'packet-statistics' (0x00000014)
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message...
> > > > > > > RAW:
> > > > > > > length = 80
> > > > > > > data =
> > > > > > > 07:00:00:80:50:00:00:00:00:00:00:00:01:00:00:00:00:00:00:
> > > > > > > 00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:
> > > > > > > 00:00:24:00:00:00:00:00:00:00:04:00:00:00:00:00:00:00:00:
> > > > > > > 00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E:
> > > > > > > 00:00:00:00
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message (translated)...
> > > > > > > Header:
> > > > > > > length = 80
> > > > > > > type = indicate-status (0x80000007)
> > > > > > > transaction = 0
> > > > > > > Fragment header:
> > > > > > > total = 1
> > > > > > > current = 0
> > > > > > > Contents:
> > > > > > > service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-
> > > > > > > 133ec2aae6df)
> > > > > > > cid = 'connect' (0x0000000c)
>
> ModemManager[5730]: [/dev/cdc-wdm0] Received message...
>
>
>
>
> So the connection is successful, and the IP configuration is
> successfully retried, but NM is immediately disconnecing the session
> anyway. Why?
>
> Manually connecting using mmcli confirms this. MM connects just
> fine.
> The issue seems to be that NM doesn't agree.
>
> But repeating the same connection a couple of times, finally makes NM
> see the too:
>
> Jan 4 16:09:11 miraculix NetworkManager[513]:
> <info> [1483542551.1790] device (cdc-wdm0): Activation: starting
> connection 'Telenor ("telenor.smart")' (3fdb56ec-485a-485c-9b05-
> d9e80a5aa52f)
> Jan 4 16:09:11 miraculix NetworkManager[513]:
> <info> [1483542551.1792] audit: op="connection-activate"
> uuid="3fdb56ec-485a-485c-9b05-d9e80a5aa52f" name="Telenor
> ("telenor.smart")" pid=3985 uid=1000 result="success"
> Jan 4 16:09:11 miraculix NetworkManager[513]:
> <info> [1483542551.1793] device (cdc-wdm0): state change:
> disconnected -> prepare (reason 'none') [30 40 0]
> Jan 4 16:09:15 miraculix kernel: [94553.112214] IPv6:
> ADDRCONF(NETDEV_UP): wwan0: link is not ready
> Jan 4 16:09:15 miraculix NetworkManager[513]:
> <info> [1483542555.4994] device (cdc-wdm0): state change: prepare ->
> config (reason 'none') [40 50 0]
> Jan 4 16:09:15 miraculix NetworkManager[513]:
> <info> [1483542555.5005] device (cdc-wdm0): state change: config ->
> failed (reason 'config-failed') [50 120 4]
> Jan 4 16:09:15 miraculix NetworkManager[513]:
> <warn> [1483542555.5037] device (cdc-wdm0): Activation: failed for
> connection 'Telenor ("telenor.smart")'
> Jan 4 16:09:15 miraculix NetworkManager[513]:
> <info> [1483542555.5064] device (cdc-wdm0): state change: failed ->
> disconnected (reason 'none') [120 30 0]
>
>
> Jan 4 16:09:23 miraculix NetworkManager[513]:
> <info> [1483542563.9279] device (cdc-wdm0): Activation: starting
> connection 'Telenor ("telenor.smart")' (3fdb56ec-485a-485c-9b05-
> d9e80a5aa52f)
> Jan 4 16:09:23 miraculix NetworkManager[513]:
> <info> [1483542563.9281] audit: op="connection-activate"
> uuid="3fdb56ec-485a-485c-9b05-d9e80a5aa52f" name="Telenor
> ("telenor.smart")" pid=3985 uid=1000 result="success"
> Jan 4 16:09:23 miraculix NetworkManager[513]:
> <info> [1483542563.9282] device (cdc-wdm0): state change:
> disconnected -> prepare (reason 'none') [30 40 0]
> Jan 4 16:09:24 miraculix kernel: [94561.831678] 8021q: adding VLAN 0
> to HW filter on device wwan0
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2324] device (cdc-wdm0): state change: prepare ->
> config (reason 'none') [40 50 0]
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2353] device (cdc-wdm0): state change: config ->
> ip-config (reason 'none') [50 70 0]
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2377] modem-broadband[cdc-wdm0]: IPv4 static
> configuration:
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2380] modem-broadband[cdc-wdm0]: address
> 10.151.134.222/30
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2382] modem-broadband[cdc-wdm0]: gateway
> 10.151.134.221
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2384] modem-broadband[cdc-wdm0]: DNS
> 193.213.112.4
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2385] modem-broadband[cdc-wdm0]: DNS
> 130.67.15.198
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2504] modem-broadband[cdc-wdm0]: IPv6 base
> configuration:
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2509] modem-broadband[cdc-wdm0]: address
> 2a02:2121:24a:2b9e:1122:7af8:7e81:2314/64
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2511] modem-broadband[cdc-wdm0]: gateway
> 2a02:2121:24a:2b9e:4963:d1af:ad8d:1d6a
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2514] modem-broadband[cdc-wdm0]: DNS
> 2001:4600:4:fff::52
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2516] modem-broadband[cdc-wdm0]: DNS
> 2001:4600:4:1fff::52
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2772] device (cdc-wdm0): state change: ip-config
> -> ip-check (reason 'none') [70 80 0]
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2897] device (cdc-wdm0): state change: ip-check
> -> secondaries (reason 'none') [80 90 0]
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.2945] device (cdc-wdm0): state change:
> secondaries -> activated (reason 'none') [90 100 0]
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.3060] policy: set 'Telenor ("telenor.smart")'
> (wwan0) as default for IPv6 routing and DNS
> Jan 4 16:09:24 miraculix NetworkManager[513]:
> <info> [1483542564.3062] device (cdc-wdm0): Activation: successful,
> device activated.
>
>
> But I fail to see any significant difference between this config and
> the
> failing one. So what's the issue here?
>
>
>
>
> Bjørn
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
More information about the ModemManager-devel
mailing list