NM fails with 'config-failed' despite successful MM connection
Bjørn Mork
bjorn at mork.no
Wed Jan 4 15:12:12 UTC 2017
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]
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
More information about the ModemManager-devel
mailing list