NM fails to make UMTS connection; deleting and recreating the connection configuration fixes it

[Mikko Rauhala]

On occasion, network-manager fails to get an UMTS network connection, and quickly refuses all future attempts to use the connection. Reconfiguration of the interface (exactly the same as before) will fix it; seems like nm may mistake a transient error for a permanent one or something. Even removing the connection description from /etc/NetworkManager/system-connections and copying the exact same file back, and attempting a reconnect will fix this particular situation. (This is what I did also in this instance.)

Relevant syslog snippet around the attempt to connect to my provider, Saunalahti:

Sep 13 16:29:14 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0)
Sep 13 16:29:14 t420s-4 modem-manager[1199]: <info> (tty/ttyACM0): released by modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4
Sep 13 16:29:14 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> disabled)
Sep 13 16:29:14 t420s-4 modem-manager[1199]: <info> (ttyACM2) closing serial port...
Sep 13 16:29:14 t420s-4 modem-manager[1199]: <info> (ttyACM2) serial port closed
Sep 13 16:29:14 t420s-4 anacron[13863]: Anacron 2.3 started on 2012-09-13
Sep 13 16:29:14 t420s-4 anacron[13863]: Normal exit (0 jobs run)
Sep 13 16:29:14 t420s-4 kernel: [24385.860392] usb 2-1.4: new high-speed USB device number 8 using ehci_hcd
Sep 13 16:29:14 t420s-4 kernel: [24385.998849] generic-usb: probe of 0003:0BDB:1912.0007 failed with error -71
Sep 13 16:29:14 t420s-4 mtp-probe: checking bus 2, device 8: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4"
Sep 13 16:29:14 t420s-4 mtp-probe: bus: 2, device: 8 was not an MTP device
Sep 13 16:29:14 t420s-4 kernel: [24386.208526] usb 2-1.4: USB disconnect, device number 8
Sep 13 16:29:15 t420s-4 kernel: [24387.176121] usb 2-1.4: new high-speed USB device number 9 using ehci_hcd
Sep 13 16:29:15 t420s-4 kernel: [24387.308285] cdc_acm 2-1.4:1.1: ttyACM0: USB ACM device
Sep 13 16:29:15 t420s-4 kernel: [24387.311154] cdc_acm 2-1.4:1.3: ttyACM1: USB ACM device
Sep 13 16:29:15 t420s-4 kernel: [24387.319164] cdc_wdm 2-1.4:1.5: cdc-wdm0: USB WDM device
Sep 13 16:29:15 t420s-4 kernel: [24387.334945] usb 2-1.4: MAC-Address: 02:80:37:ec:02:00
Sep 13 16:29:15 t420s-4 kernel: [24387.335134] cdc_ncm 2-1.4:1.6: usb0: register 'cdc_ncm' at usb-0000:00:1d.0-1.4, CDC NCM, 02:80:37:ec:02:00
Sep 13 16:29:15 t420s-4 kernel: [24387.335731] cdc_wdm 2-1.4:1.8: cdc-wdm1: USB WDM device
Sep 13 16:29:15 t420s-4 kernel: [24387.336151] cdc_acm 2-1.4:1.9: ttyACM2: USB ACM device
Sep 13 16:29:15 t420s-4 mtp-probe: checking bus 2, device 9: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4"
Sep 13 16:29:15 t420s-4 mtp-probe: bus: 2, device: 9 was not an MTP device
Sep 13 16:29:15 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:29:15 t420s-4 modem-manager[1199]: <info> (ttyACM2) opening serial port...
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0)
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0): no ifupdown configuration found.
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: <warn> failed to allocate link cache: (-10) Operation not supported
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: <info> (usb0): carrier is OFF
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: <error> [1347542955.958115] [nm-device-ethernet.c:456] real_update_permanent_hw_address(): (usb0): unable to read permanent MAC address (error 0)
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: <info> (usb0): new Ethernet device (driver: 'cdc_ncm' ifindex: 80)
Sep 13 16:29:15 t420s-4 NetworkManager[1278]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/4
Sep 13 16:29:15 t420s-4 modem-manager[1199]: <info> (ttyACM1) opening serial port...
Sep 13 16:29:15 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port usb0
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM0
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM2) closing serial port...
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM2) serial port closed
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM1) closing serial port...
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM1) serial port closed
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM2
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM1
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:29:16 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:29:16 t420s-4 NetworkManager[1278]: <info> WWAN now disabled by management service
Sep 13 16:29:16 t420s-4 NetworkManager[1278]: <info> (usb0): new GSM/UMTS device (driver: 'cdc_ncm' ifindex: 80)
Sep 13 16:29:16 t420s-4 NetworkManager[1278]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/5
Sep 13 16:29:22 t420s-4 NetworkManager[1278]: <info> WiFi now disabled by radio killswitch
Sep 13 16:29:23 t420s-4 kernel: [24394.593705] usb 1-1.4: new full-speed USB device number 6 using ehci_hcd
Sep 13 16:29:23 t420s-4 bluetoothd[923]: HCI dev 0 registered
Sep 13 16:29:23 t420s-4 bluetoothd[923]: Listening for HCI events on hci0
Sep 13 16:29:23 t420s-4 bluetoothd[923]: HCI dev 0 up
Sep 13 16:29:23 t420s-4 bluetoothd[923]: Adapter /org/bluez/923/hci0 has been enabled
Sep 13 16:29:25 t420s-4 kernel: [24396.908146] init: aiccu pre-start process (13936) terminated with status 1
Sep 13 16:29:25 t420s-4 aiccu[14079]: Couldn't resolve host tic.sixxs.net, service 3874
Sep 13 16:29:25 t420s-4 aiccu[14079]: Couldn't connect to the TIC server tic.sixxs.net
Sep 13 16:29:25 t420s-4 aiccu[14079]: Couldn't retrieve first tunnel for the above reason, aborting
Sep 13 16:29:25 t420s-4 kernel: [24396.917393] init: aiccu post-stop process (14076) terminated with status 255
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> wake requested (sleeping: yes enabled: yes)
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> waking up and re-enabling...
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (eth0): now managed
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (eth0): bringing up device.
Sep 13 16:29:25 t420s-4 kernel: [24397.280640] e1000e 0000:00:19.0: irq 50 for MSI/MSI-X
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (eth0): preparing device.
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (eth0): deactivating device (reason 'managed') [2]
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:29:25 NetworkManager[1278]: last message repeated 3 times
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (wlan0): now managed
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (wlan0): bringing up device.
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (wlan0): deactivating device (reason 'managed') [2]
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (usb0): now managed
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (usb0): bringing up device.
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'managed') [2]
Sep 13 16:29:25 t420s-4 kernel: [24397.384682] e1000e 0000:00:19.0: irq 50 for MSI/MSI-X
Sep 13 16:29:25 t420s-4 kernel: [24397.385423] ADDRCONF(NETDEV_UP): eth0: link is not ready
Sep 13 16:29:25 t420s-4 kernel: [24397.387466] ADDRCONF(NETDEV_UP): usb0: link is not ready
Sep 13 16:29:25 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> Activation (usb0) starting connection 'Saunalahti'
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) started...
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) complete.
Sep 13 16:29:27 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:29:27 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (disabled -> enabling)
Sep 13 16:29:27 t420s-4 modem-manager[1199]: Invalid error code: 276
Sep 13 16:29:27 t420s-4 modem-manager[1199]: <info> (ttyACM2) opening serial port...
Sep 13 16:29:27 t420s-4 modem-manager[1199]: <info> (ttyACM0): using PDU mode for SMS
Sep 13 16:29:27 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabling -> enabled)
Sep 13 16:29:27 t420s-4 NetworkManager[1278]: <info> WWAN now enabled by management service
Sep 13 16:29:28 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> searching)
Sep 13 16:29:28 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (searching -> enabled)
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:30:27 t420s-4 avahi-daemon[933]: Withdrawing workstation service for usb0.
Sep 13 16:30:27 t420s-4 kernel: [24458.888953] usb 2-1.4: USB disconnect, device number 9
Sep 13 16:30:27 t420s-4 kernel: [24458.889610] cdc_ncm 2-1.4:1.6: usb0: unregister 'cdc_ncm' usb-0000:00:1d.0-1.4, CDC NCM
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0)
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> (usb0): now unmanaged
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: prepare -> unmanaged (reason 'removed') [40 10 36]
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'removed') [36]
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <warn> (80) failed to find interface name for index
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: nm_system_iface_flush_routes: assertion `iface != NULL' failed
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <warn> (80) failed to find interface name for index
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <warn> (80) failed to find interface name for index
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: nm_system_iface_flush_routes: assertion `iface != NULL' failed
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <warn> (80) failed to find interface name for index
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> (net/usb0): released by modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> disabled)
Sep 13 16:30:27 t420s-4 modem-manager[1199]: mm_callback_info_schedule: assertion `info->pending_id == 0' failed
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> (ttyACM2) closing serial port...
Sep 13 16:30:27 t420s-4 modem-manager[1199]: <info> (ttyACM2) serial port closed
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> (usb0): cleaning up...
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <warn> (80) failed to find interface name for index
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: (nm-system.c:685):nm_system_iface_get_flags: runtime check failed: (iface != NULL)
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <error> [1347543027.510077] [nm-system.c:687] nm_system_iface_get_flags(): (unknown): failed to get interface link object
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:30:27 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:30:27 t420s-4 kernel: [24459.228746] usb 2-1.4: new high-speed USB device number 10 using ehci_hcd
Sep 13 16:30:27 t420s-4 kernel: [24459.366789] generic-usb: probe of 0003:0BDB:1912.0008 failed with error -71
Sep 13 16:30:27 t420s-4 mtp-probe: checking bus 2, device 10: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4"
Sep 13 16:30:27 t420s-4 mtp-probe: bus: 2, device: 10 was not an MTP device
Sep 13 16:30:28 t420s-4 kernel: [24459.400792] usb 2-1.4: USB disconnect, device number 10
Sep 13 16:30:34 t420s-4 kernel: [24465.742632] usb 2-1.4: new high-speed USB device number 11 using ehci_hcd
Sep 13 16:30:34 t420s-4 kernel: [24465.880703] generic-usb: probe of 0003:0BDB:1912.0009 failed with error -71
Sep 13 16:30:34 t420s-4 kernel: [24465.881044] usb 2-1.4: USB disconnect, device number 11
Sep 13 16:30:36 t420s-4 kernel: [24467.534027] usb 2-1.4: new high-speed USB device number 12 using ehci_hcd
Sep 13 16:30:36 t420s-4 kernel: [24467.667301] cdc_acm 2-1.4:1.1: ttyACM0: USB ACM device
Sep 13 16:30:36 t420s-4 kernel: [24467.670201] cdc_acm 2-1.4:1.3: ttyACM1: USB ACM device
Sep 13 16:30:36 t420s-4 kernel: [24467.678459] cdc_wdm 2-1.4:1.5: cdc-wdm0: USB WDM device
Sep 13 16:30:36 t420s-4 kernel: [24467.693990] usb 2-1.4: MAC-Address: 02:80:37:ec:02:00
Sep 13 16:30:36 t420s-4 kernel: [24467.694192] cdc_ncm 2-1.4:1.6: usb0: register 'cdc_ncm' at usb-0000:00:1d.0-1.4, CDC NCM, 02:80:37:ec:02:00
Sep 13 16:30:36 t420s-4 kernel: [24467.694776] cdc_wdm 2-1.4:1.8: cdc-wdm1: USB WDM device
Sep 13 16:30:36 t420s-4 kernel: [24467.695146] cdc_acm 2-1.4:1.9: ttyACM2: USB ACM device
Sep 13 16:30:36 t420s-4 mtp-probe: checking bus 2, device 12: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4"
Sep 13 16:30:36 t420s-4 mtp-probe: bus: 2, device: 12 was not an MTP device
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM1) opening serial port...
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0, iface: usb0): no ifupdown configuration found.
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <warn> failed to allocate link cache: (-10) Operation not supported
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): carrier is OFF
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <error> [1347543036.340841] [nm-device-ethernet.c:456] real_update_permanent_hw_address(): (usb0): unable to read permanent MAC address (error 0)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): new Ethernet device (driver: 'cdc_ncm' ifindex: 81)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/6
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): now managed
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): bringing up device.
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): preparing device.
Sep 13 16:30:36 t420s-4 kernel: [24467.730768] ADDRCONF(NETDEV_UP): usb0: link is not ready
Sep 13 16:30:36 t420s-4 kernel: [24467.734813] cdc_ncm: usb0: network connection: disconnected
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'managed') [2]
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> Added default wired connection 'Wired connection 2' for /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4/2-1.4:1.6/net/usb0
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM2) opening serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port usb0
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM0
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM1) closing serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM1) serial port closed
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM1
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM2) closing serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM2) serial port closed
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (Ericsson MBM): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4 claimed port ttyACM2
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:30:36 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): now unmanaged
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unavailable -> unmanaged (reason 'removed') [20 10 36]
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): cleaning up...
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): taking down device.
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> WWAN now disabled by management service
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): new GSM/UMTS device (driver: 'cdc_ncm' ifindex: 81)
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/7
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): now managed
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): bringing up device.
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'managed') [2]
Sep 13 16:30:36 t420s-4 kernel: [24468.270116] ADDRCONF(NETDEV_UP): usb0: link is not ready
Sep 13 16:30:36 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> Activation (usb0) starting connection 'Saunalahti'
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) started...
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) complete.
Sep 13 16:30:39 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:30:39 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Sep 13 16:30:39 t420s-4 modem-manager[1199]: Invalid error code: 276
Sep 13 16:30:39 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> disabled)
Sep 13 16:30:39 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:30:39 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <warn> GSM modem enable failed: (32) Unknown error
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: prepare -> failed (reason 'modem-init-failed') [40 120 28]
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <warn> Activation (usb0) failed.
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Sep 13 16:30:39 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'none') [0]
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> Activation (usb0) starting connection 'Saunalahti'
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) started...
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) complete.
Sep 13 16:30:40 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:30:40 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Sep 13 16:30:40 t420s-4 modem-manager[1199]: Invalid error code: 276
Sep 13 16:30:40 t420s-4 modem-manager[1199]: Invalid error code: 272
Sep 13 16:30:40 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> disabled)
Sep 13 16:30:40 t420s-4 modem-manager[1199]: <info> (ttyACM0) closing serial port...
Sep 13 16:30:40 t420s-4 modem-manager[1199]: <info> (ttyACM0) serial port closed
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <warn> GSM modem enable failed: (32) Unknown error
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: prepare -> failed (reason 'modem-init-failed') [40 120 28]
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <warn> Activation (usb0) failed.
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Sep 13 16:30:40 t420s-4 NetworkManager[1278]: <info> (usb0): deactivating device (reason 'none') [0]
Sep 13 16:30:47 t420s-4 NetworkManager[1278]: keyfile: removed /etc/NetworkManager/system-connections/Saunalahti.
Sep 13 16:30:49 t420s-4 NetworkManager[1278]: keyfile: updating /etc/NetworkManager/system-connections/Saunalahti
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> Activation (usb0) starting connection 'Saunalahti'
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) scheduled...
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) started...
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 1 of 5 (Device Prepare) complete.
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> (ttyACM0) opening serial port...
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Sep 13 16:30:51 t420s-4 modem-manager[1199]: Invalid error code: 276
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> (ttyACM1) opening serial port...
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> (ttyACM0): using PDU mode for SMS
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> enabled)
Sep 13 16:30:51 t420s-4 NetworkManager[1278]: <info> WWAN now enabled by management service
Sep 13 16:30:51 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabled -> registered)
Sep 13 16:30:52 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (registered -> connecting)
Sep 13 16:30:55 t420s-4 modem-manager[1199]: <info> Modem /org/freedesktop/ModemManager/Modems/2: state changed (connecting -> connected)
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 2 of 5 (Device Configure) scheduled...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 2 of 5 (Device Configure) starting...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: prepare -> config (reason 'none') [40 50 0]
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): bringing up device.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 2 of 5 (Device Configure) successful.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 3 of 5 (IP Configure Start) scheduled.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 2 of 5 (Device Configure) complete.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 3 of 5 (IP Configure Start) started...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: config -> ip-config (reason 'none') [50 70 0]
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> dhclient started with pid 14356
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 3 of 5 (IP Configure Start) complete.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) started...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Sep 13 16:30:55 t420s-4 dhclient: Internet Systems Consortium DHCP Client 4.1-ESV-R4
Sep 13 16:30:55 t420s-4 dhclient: Copyright 2004-2011 Internet Systems Consortium.
Sep 13 16:30:55 t420s-4 dhclient: All rights reserved.
Sep 13 16:30:55 t420s-4 dhclient: For info, please visit https://www.isc.org/software/dhcp/
Sep 13 16:30:55 t420s-4 dhclient:
Sep 13 16:30:55 t420s-4 kernel: [24486.455826] ADDRCONF(NETDEV_UP): usb0: link is not ready
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): DHCPv4 state changed nbi -> preinit
Sep 13 16:30:55 t420s-4 kernel: [24486.464734] cdc_ncm: usb0: 21 mbit/s downlink 5 mbit/s uplink
Sep 13 16:30:55 t420s-4 kernel: [24486.472732] cdc_ncm: usb0: network connection: connected
Sep 13 16:30:55 t420s-4 kernel: [24486.473257] ADDRCONF(NETDEV_CHANGE): usb0: link becomes ready
Sep 13 16:30:55 t420s-4 dhclient: Listening on LPF/usb0/02:80:37:ec:02:00
Sep 13 16:30:55 t420s-4 dhclient: Sending on LPF/usb0/02:80:37:ec:02:00
Sep 13 16:30:55 t420s-4 dhclient: Sending on Socket/fallback
Sep 13 16:30:55 t420s-4 dhclient: DHCPREQUEST of 193.66.78.198 on usb0 to 255.255.255.255 port 67
Sep 13 16:30:55 t420s-4 dhclient: DHCPNAK from 193.66.93.105
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): DHCPv4 state changed preinit -> expire
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): DHCPv4 state changed expire -> preinit
Sep 13 16:30:55 t420s-4 dhclient: DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 3
Sep 13 16:30:55 t420s-4 dhclient: DHCPREQUEST of 193.66.93.108 on usb0 to 255.255.255.255 port 67
Sep 13 16:30:55 t420s-4 dhclient: DHCPOFFER of 193.66.93.108 from 193.66.93.105
Sep 13 16:30:55 t420s-4 dhclient: DHCPACK of 193.66.93.108 from 193.66.93.105
Sep 13 16:30:55 t420s-4 dhclient: bound to 193.66.93.108 -- renewal in 40474 seconds.
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> (usb0): DHCPv4 state changed preinit -> bound
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> address 193.66.93.108
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> prefix 29 (255.255.255.248)
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> gateway 193.66.93.106
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> nameserver '195.197.54.100'
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> nameserver '195.74.0.47'
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Sep 13 16:30:55 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 5 of 5 (IPv4 Commit) started...
Sep 13 16:30:55 t420s-4 avahi-daemon[933]: Joining mDNS multicast group on interface usb0.IPv4 with address 193.66.93.108.
Sep 13 16:30:55 t420s-4 avahi-daemon[933]: New relevant interface usb0.IPv4 for mDNS.
Sep 13 16:30:55 t420s-4 avahi-daemon[933]: Registering new address record for 193.66.93.108 on usb0.IPv4.
Sep 13 16:30:56 t420s-4 dnsmasq[13252]: exiting on receipt of SIGTERM
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> DNS: starting dnsmasq...
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> (usb0): writing resolv.conf to /sbin/resolvconf
Sep 13 16:30:56 t420s-4 dnsmasq[14362]: started, version 2.59 cache disabled
Sep 13 16:30:56 t420s-4 dnsmasq[14362]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN
Sep 13 16:30:56 t420s-4 dnsmasq[14362]: using nameserver 195.74.0.47#53
Sep 13 16:30:56 t420s-4 dnsmasq[14362]: using nameserver 195.197.54.100#53
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> Clearing nscd hosts cache.
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> (usb0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> Policy set 'Saunalahti' (usb0) as default for IPv4 routing and DNS.
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> Activation (usb0) successful, device activated.
Sep 13 16:30:56 t420s-4 dbus[869]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Sep 13 16:30:56 t420s-4 NetworkManager[1278]: <info> Activation (usb0) Stage 5 of 5 (IPv4 Commit) complete.
Sep 13 16:30:56 t420s-4 dbus[869]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Sep 13 16:30:56 t420s-4 ntpd[10555]: ntpd exiting on signal 15
Sep 13 16:30:56 t420s-4 avahi-daemon[933]: Joining mDNS multicast group on interface usb0.IPv6 with address fe80::80:37ff:feec:200.
Sep 13 16:30:56 t420s-4 avahi-daemon[933]: New relevant interface usb0.IPv6 for mDNS.
Sep 13 16:30:56 t420s-4 avahi-daemon[933]: Registering new address record for fe80::80:37ff:feec:200 on usb0.*.
Sep 13 16:30:58 t420s-4 aiccu[14480]: Successfully retrieved tunnel information for T11711
Sep 13 16:30:58 t420s-4 aiccu[14485]: AICCU running as PID 14485
Sep 13 16:30:58 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/sixxs, iface: sixxs)
Sep 13 16:30:58 t420s-4 NetworkManager[1278]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/sixxs, iface: sixxs): no ifupdown configuration found.
Sep 13 16:30:58 t420s-4 aiccu[14485]: [AYIYA-start] : Anything in Anything (draft-02)
Sep 13 16:30:58 t420s-4 aiccu[14485]: [AYIYA-tun->tundev] : (Socket to TUN) started
Sep 13 16:31:07 t420s-4 kernel: [24499.163623] sixxs: no IPv6 routers present
Sep 13 16:31:09 t420s-4 ntpdate[14452]: step time server 194.100.2.198 offset 0.535743 sec
Sep 13 16:31:09 t420s-4 ntpd[14539]: ntpd 4.2.6p3@1.2290-o Tue Jun 5 20:12:08 UTC 2012 (1)
Sep 13 16:31:09 t420s-4 ntpd[14540]: proto: precision = 0.107 usec
Sep 13 16:31:09 t420s-4 ntpd[14540]: ntp_io: estimated max descriptors: 2144, initial socket boundary: 16
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen and drop on 1 v6wildcard :: UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 2 lo 127.0.0.1 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 3 usb0 193.66.93.108 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 4 usb0 fe80::80:37ff:feec:200 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 5 sixxs fe80::14b8:100:1d8:2 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 6 sixxs 2001:14b8:100:1d8::2 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listen normally on 7 lo ::1 UDP 123
Sep 13 16:31:09 t420s-4 ntpd[14540]: peers refreshed
Sep 13 16:31:09 t420s-4 ntpd[14540]: Listening on routing socket on fd #24 for interface updates
Sep 13 16:32:14 t420s-4 kernel: [24565.345808] CPU2: Package power limit notification (total events = 151)
Sep 13 16:32:14 t420s-4 kernel: [24565.345811] CPU3: Package power limit notification (total events = 151)
Sep 13 16:32:14 t420s-4 kernel: [24565.345814] CPU1: Package power limit notification (total events = 151)
Sep 13 16:32:14 t420s-4 kernel: [24565.345817] CPU0: Package power limit notification (total events = 151)
Sep 13 16:32:14 t420s-4 kernel: [24565.356828] CPU1: Package power limit normal
Sep 13 16:32:14 t420s-4 kernel: [24565.356831] CPU3: Package power limit normal
Sep 13 16:32:14 t420s-4 kernel: [24565.356833] CPU2: Package power limit normal
Sep 13 16:32:14 t420s-4 kernel: [24565.356835] CPU0: Package power limit normal
Sep 13 16:35:28 t420s-4 kernel: [24759.079540] usb 2-1.2: USB disconnect, device number 7
Sep 13 16:35:36 t420s-4 kernel: [24767.213034] usb 2-1.2: new full-speed USB device number 13 using ehci_hcd
Sep 13 16:35:36 t420s-4 kernel: [24767.309734] input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2:1.0/input/input20
Sep 13 16:35:36 t420s-4 kernel: [24767.309856] generic-usb 0003:046D:C526.000A: input,hidraw0: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-0000:00:1d.0-1.2/input0
Sep 13 16:35:36 t420s-4 kernel: [24767.311908] input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2/2-1.2:1.1/input/input21
Sep 13 16:35:36 t420s-4 kernel: [24767.312161] generic-usb 0003:046D:C526.000B: input,hiddev0,hidraw1: USB HID v1.11 Device [Logitech USB Receiver] on usb-0000:00:1d.0-1.2/input1
Sep 13 16:35:36 t420s-4 mtp-probe: checking bus 2, device 13: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.2"
Sep 13 16:35:36 t420s-4 mtp-probe: bus: 2, device: 13 was not an MTP device

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: network-manager 0.9.4.0-0ubuntu4.1
Uname: Linux 3.4.0-030400-generic x86_64
ApportVersion: 2.0.1-0ubuntu13
Architecture: amd64
CRDA: Error: [Errno 2] No such file or directory
Date: Thu Sep 13 16:41:11 2012
IpRoute:
 default via 193.66.93.106 dev usb0 proto static
 169.254.0.0/16 dev usb0 scope link metric 1000
 193.66.93.104/29 dev usb0 proto kernel scope link src 193.66.93.108 metric 8
NetworkManager.state:
 [main]
 NetworkingEnabled=true
 WirelessEnabled=true
 WWANEnabled=false
 WimaxEnabled=true
SourcePackage: network-manager
UpgradeStatus: No upgrade log present (probably fresh install)
nmcli-dev:
 DEVICE TYPE STATE DBUS-PATH
 usb0 gsm connected /org/freedesktop/NetworkManager/Devices/7
 wlan0 802-11-wireless unavailable /org/freedesktop/NetworkManager/Devices/1
 eth0 802-3-ethernet unavailable /org/freedesktop/NetworkManager/Devices/0
nmcli-nm:
 RUNNING VERSION STATE NET-ENABLED WIFI-HARDWARE WIFI WWAN-HARDWARE WWAN
 running 0.9.4.0 connected enabled enabled disabled enabled disabled

[Mikko Rauhala (mjr-iki)]

As far as I can see, this doesn't happen anymore. (Artifact of using Xubuntu desktop at the time? Seems unlikely though.)

[Marius B. Kotsbak (mariusko)]

This is similar to bug #894124.