broadband connection establishes then drop after a few seconds

Bug #1462356 reported by Louis Bouchard
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
network-manager (Ubuntu)
Triaged
Undecided
Unassigned

Bug Description

When connecting a cell phone to share the cell network connection, the link gets established then drops after a few seconds. Doing the same on Trusty works correctly.

Here is the end of a successful connection on Trusty :
==========================================
Jun 5 14:13:54 trusty NetworkManager[850]: <info> Activation (usb0) successful, device activated.
Jun 5 14:13:54 trusty dbus[756]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jun 5 14:13:54 trusty dbus[756]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jun 5 14:14:05 trusty ModemManager[769]: <info> Creating modem with plugin 'Generic' and '2' ports
Jun 5 14:14:05 trusty ModemManager[769]: <info> Modem for device at '/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.4' successfully created
Jun 5 14:14:09 trusty ModemManager[769]: <warn> couldn't load Manufacturer: 'Serial command timed out'
Jun 5 14:14:11 trusty NetworkManager[850]: <info> (usb0): IP6 addrconf timed out or failed.
Jun 5 14:14:11 trusty NetworkManager[850]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Jun 5 14:14:11 trusty NetworkManager[850]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) started...
Jun 5 14:14:11 trusty NetworkManager[850]: <info> Activation (usb0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Jun 5 14:14:12 trusty ModemManager[769]: <warn> couldn't load Model: 'Serial command timed out'
Jun 5 14:14:13 trusty ntpdate[2828]: no server suitable for synchronization found
Jun 5 14:14:15 trusty ModemManager[769]: <warn> couldn't load Revision: 'Serial command timed out'
Jun 5 14:14:18 trusty ModemManager[769]: <warn> couldn't load Equipment Identifier: 'Serial command timed out'
Jun 5 14:14:22 trusty ModemManager[769]: <warn> couldn't load IMEI: 'Serial command timed out'
Jun 5 14:14:22 trusty ModemManager[769]: <info> Modem: state changed (unknown -> disabled)
Jun 5 14:14:22 trusty NetworkManager[850]: <warn> (ttyACM0): failed to look up interface index
Jun 5 14:14:22 trusty NetworkManager[850]: <info> (ttyACM0): new Broadband device (driver: 'cdc_acm, cdc_ether' ifindex: 0)
Jun 5 14:14:22 trusty NetworkManager[850]: <info> (ttyACM0): exported as /org/freedesktop/NetworkManager/Devices/3
Jun 5 14:14:22 trusty NetworkManager[850]: <info> (ttyACM0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 5 14:14:22 trusty NetworkManager[850]: <info> (ttyACM0): deactivating device (reason 'managed') [2]
Jun 5 14:14:22 trusty NetworkManager[850]: <info> (ttyACM0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jun 5 14:14:58 trusty wpa_supplicant[1063]: wlan0: CTRL-EVENT-SCAN-STARTED
Jun 5 14:15:02 trusty wpa_supplicant[1063]: nl80211: send_and_recv->nl_recvmsgs failed: -33

A connection using the same cell phone on Wily has this log :
================================================
Jun 5 14:20:30 wily NetworkManager[836]: <info> Activation (usb0) successful, device activated.
Jun 5 14:20:30 wily dbus[897]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Jun 5 14:20:30 wily systemd[1]: Starting Network Manager Script Dispatcher Service...
Jun 5 14:20:30 wily NetworkManager[836]: <warn> dnsmasq appeared on DBus: :1.81
Jun 5 14:20:30 wily NetworkManager[836]: <info> Writing DNS information to /sbin/resolvconf
Jun 5 14:20:30 wily dnsmasq[2869]: configuration des serveurs amonts à partir de DBus
Jun 5 14:20:30 wily dnsmasq[2869]: utilise le serveur de nom 192.168.42.129#53
Jun 5 14:20:30 wily dbus[897]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jun 5 14:20:30 wily systemd[1]: Started Network Manager Script Dispatcher Service.
Jun 5 14:20:30 wily nm-dispatcher: Dispatching action 'up' for usb0
Jun 5 14:20:30 wily NetworkManager[836]: status: Impossible de se connecter à Upstart: Failed to connect to socket /com/ubuntu/upstart: Connexion refusée
Jun 5 14:20:30 wily systemd[1]: Stopping LSB: Start NTP daemon...
Jun 5 14:20:30 wily ntp[3063]: * Stopping NTP server ntpd
Jun 5 14:20:30 wily ntpd[1045]: ntpd exiting on signal 15
Jun 5 14:20:30 wily ntp[3063]: ...done.
Jun 5 14:20:30 wily systemd[1]: Stopped LSB: Start NTP daemon.
Jun 5 14:20:30 wily systemd[1]: Reloaded OpenBSD Secure Shell server.
Jun 5 14:20:30 wily ntpdate[3075]: name server cannot be used: Temporary failure in name resolution (-3)
Jun 5 14:20:30 wily systemd[1]: Starting LSB: Start NTP daemon...
Jun 5 14:20:30 wily ntp[3138]: * Starting NTP server ntpd
Jun 5 14:20:30 wily ntpd[3149]: ntpd 4.2.6p5@1.2349-o Mon Apr 13 17:00:14 UTC 2015 (1)
Jun 5 14:20:30 wily ntpd[3158]: proto: precision = 0.171 usec
Jun 5 14:20:30 wily ntpd[3158]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Jun 5 14:20:30 wily ntpd[3158]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jun 5 14:20:30 wily ntp[3138]: ...done.
Jun 5 14:20:30 wily systemd[1]: Started LSB: Start NTP daemon.
Jun 5 14:20:30 wily ntpd[3158]: Listen and drop on 1 v6wildcard :: UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 3 lxcbr0 10.0.3.1 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 4 virbr0 192.168.122.1 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 5 usb0 192.168.42.109 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 6 lo ::1 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 7 lxcbr0 fe80::4e2:4cff:fe0e:2360 UDP 123
Jun 5 14:20:30 wily ntpd[3158]: Listen normally on 8 usb0 fe80::8cf4:f3ff:fe50:cfdd UDP 123
Jun 5 14:20:30 wily ntpd[3158]: peers refreshed
Jun 5 14:20:30 wily ntpd[3158]: Listening on routing socket on fd #25 for interface updates
Jun 5 14:20:30 wily ntpd[3158]: Deferring DNS for 0.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3158]: Deferring DNS for 1.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3158]: Deferring DNS for 2.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3158]: Deferring DNS for 3.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3158]: Deferring DNS for ntp.ubuntu.com 1
Jun 5 14:20:30 wily ntpd[3183]: signal_no_reset: signal 17 had flags 4000000
Jun 5 14:20:30 wily systemd[1]: Stopping LSB: Start NTP daemon...
Jun 5 14:20:30 wily ntp[3216]: * Stopping NTP server ntpd
Jun 5 14:20:30 wily ntpd[3158]: ntpd exiting on signal 15
Jun 5 14:20:30 wily ntp[3216]: ...done.
Jun 5 14:20:30 wily systemd[1]: Stopped LSB: Start NTP daemon.
Jun 5 14:20:30 wily systemd[1]: Reloaded OpenBSD Secure Shell server.
Jun 5 14:20:30 wily ntpdate[3229]: name server cannot be used: Temporary failure in name resolution (-3)
Jun 5 14:20:30 wily systemd[1]: Starting LSB: Start NTP daemon...
Jun 5 14:20:30 wily ntp[3266]: * Starting NTP server ntpd
Jun 5 14:20:30 wily ntpd[3274]: ntpd 4.2.6p5@1.2349-o Mon Apr 13 17:00:14 UTC 2015 (1)
Jun 5 14:20:30 wily ntpd[3275]: proto: precision = 0.121 usec
Jun 5 14:20:30 wily ntpd[3275]: ntp_io: estimated max descriptors: 1024, initial socket boundary: 16
Jun 5 14:20:30 wily ntpd[3275]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jun 5 14:20:30 wily ntp[3266]: ...done.
Jun 5 14:20:30 wily systemd[1]: Started LSB: Start NTP daemon.
Jun 5 14:20:30 wily ntpd[3275]: Listen and drop on 1 v6wildcard :: UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 3 lxcbr0 10.0.3.1 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 4 virbr0 192.168.122.1 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 5 usb0 192.168.42.109 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 6 lo ::1 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 7 lxcbr0 fe80::4e2:4cff:fe0e:2360 UDP 123
Jun 5 14:20:30 wily ntpd[3275]: Listen normally on 8 usb0 fe80::8cf4:f3ff:fe50:cfdd UDP 123
Jun 5 14:20:30 wily ntpd[3275]: peers refreshed
Jun 5 14:20:30 wily ntpd[3275]: Listening on routing socket on fd #25 for interface updates
Jun 5 14:20:30 wily ntpd[3275]: Deferring DNS for 0.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3275]: Deferring DNS for 1.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3275]: Deferring DNS for 2.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3275]: Deferring DNS for 3.ubuntu.pool.ntp.org 1
Jun 5 14:20:30 wily ntpd[3275]: Deferring DNS for ntp.ubuntu.com 1
Jun 5 14:20:30 wily ntpd[3277]: signal_no_reset: signal 17 had flags 4000000
Jun 5 14:20:32 wily ntpd_intres[3183]: parent died before we finished, exiting
Jun 5 14:20:32 wily ntpd_intres[3277]: DNS 0.ubuntu.pool.ntp.org -> 109.69.184.209
Jun 5 14:20:32 wily ntpd_intres[3277]: DNS 1.ubuntu.pool.ntp.org -> 91.121.169.20
Jun 5 14:20:32 wily ntpd_intres[3277]: DNS 2.ubuntu.pool.ntp.org -> 212.83.179.156
Jun 5 14:20:32 wily ntpd_intres[3277]: DNS 3.ubuntu.pool.ntp.org -> 212.43.246.10
Jun 5 14:20:32 wily ntpd_intres[3277]: DNS ntp.ubuntu.com -> 91.189.89.199
Jun 5 14:20:37 wily ntpd_intres[1048]: parent died before we finished, exiting
Jun 5 14:20:40 wily ModemManager[818]: <info> Creating modem with plugin 'Generic' and '2' ports
Jun 5 14:20:40 wily ModemManager[818]: <info> Modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-4' successfully created
Jun 5 14:20:44 wily ModemManager[818]: <warn> couldn't load Manufacturer: 'Serial command timed out'
Jun 5 14:20:47 wily ModemManager[818]: <warn> couldn't load Model: 'Serial command timed out'
Jun 5 14:20:50 wily ModemManager[818]: <warn> couldn't load Revision: 'Serial command timed out'
Jun 5 14:20:53 wily ModemManager[818]: <warn> couldn't load Equipment Identifier: 'Serial command timed out'
Jun 5 14:20:57 wily ModemManager[818]: <warn> couldn't load IMEI: 'Serial command timed out'
Jun 5 14:20:57 wily ModemManager[818]: <info> Modem: state changed (unknown -> disabled)
Jun 5 14:20:57 wily NetworkManager[836]: <warn> (ttyACM0): failed to look up interface index
Jun 5 14:20:57 wily NetworkManager[836]: <info> (usb0): device state change: activated -> unmanaged (reason 'removed') [100 10 36]
Jun 5 14:20:57 wily NetworkManager[836]: <info> (usb0): deactivating device (reason 'removed') [36]
Jun 5 14:20:57 wily NetworkManager[836]: <info> (usb0): canceled DHCP transaction, DHCP client pid 2864
Jun 5 14:20:57 wily kernel: [ 658.934305] cdc_ether 1-4:1.3 usb0: kevent 12 may have been dropped
Jun 5 14:20:57 wily kernel: [ 658.934315] cdc_ether 1-4:1.3 usb0: kevent 12 may have been dropped
Jun 5 14:20:57 wily dnsmasq[2503]: reading /etc/resolv.conf
Jun 5 14:20:57 wily dnsmasq[2503]: using nameserver 127.0.1.1#53
Jun 5 14:20:57 wily NetworkManager[836]: _nl_get_vtable: assertion 'vtable.handle' failed
Jun 5 14:20:57 wily avahi-daemon[812]: Withdrawing address record for fe80::8cf4:f3ff:fe50:cfdd on usb0.
Jun 5 14:20:57 wily avahi-daemon[812]: Leaving mDNS multicast group on interface usb0.IPv6 with address fe80::8cf4:f3ff:fe50:cfdd.
Jun 5 14:20:57 wily avahi-daemon[812]: Interface usb0.IPv6 no longer relevant for mDNS.
Jun 5 14:20:57 wily avahi-daemon[812]: Withdrawing address record for 192.168.42.109 on usb0.
Jun 5 14:20:57 wily avahi-daemon[812]: Leaving mDNS multicast group on interface usb0.IPv4 with address 192.168.42.109.
Jun 5 14:20:57 wily avahi-daemon[812]: Interface usb0.IPv4 no longer relevant for mDNS.
Jun 5 14:20:57 wily dnsmasq[1559]: Lecture de /etc/resolv.conf
Jun 5 14:20:57 wily dnsmasq[1559]: utilise le serveur de nom 127.0.1.1#53
Jun 5 14:20:57 wily NetworkManager[836]: <info> Writing DNS information to /sbin/resolvconf
Jun 5 14:20:57 wily dnsmasq[2869]: configuration des serveurs amonts à partir de DBus
Jun 5 14:20:57 wily NetworkManager[836]: <info> NetworkManager state is now CONNECTED_LOCAL
Jun 5 14:20:57 wily NetworkManager[836]: <info> (usb0): link disconnected
Jun 5 14:20:57 wily NetworkManager[836]: <info> NetworkManager state is now DISCONNECTED
Jun 5 14:20:57 wily kernel: [ 658.950918] IPv6: ADDRCONF(NETDEV_UP): usb0: link is not ready
Jun 5 14:20:57 wily dbus[897]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Jun 5 14:20:57 wily systemd[1]: Starting Network Manager Script Dispatcher Service...
Jun 5 14:20:57 wily dbus[897]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jun 5 14:20:57 wily nm-dispatcher: Dispatching action 'down' for usb0
Jun 5 14:20:57 wily systemd[1]: Started Network Manager Script Dispatcher Service.
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): new Broadband device (driver: 'cdc_acm, cdc_ether' ifindex: 0)
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): exported as /org/freedesktop/NetworkManager/Devices/7
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 5 14:20:57 wily ModemManager[818]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): preparing device
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): modem state 'enabling'
Jun 5 14:20:57 wily NetworkManager[836]: <info> (ttyACM0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jun 5 14:20:58 wily ModemManager[818]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
Jun 5 14:20:58 wily ModemManager[818]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
Jun 5 14:20:58 wily ModemManager[818]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> registered)
Jun 5 14:20:58 wily NetworkManager[836]: <info> (ttyACM0): modem state changed, 'enabling' --> 'registered' (reason: user-requested)
Jun 5 14:20:58 wily NetworkManager[836]: <info> (ttyACM0): modem re-registered; re-checking autoconnect
Jun 5 14:20:59 wily ntpd[3275]: Deleting interface #8 usb0, fe80::8cf4:f3ff:fe50:cfdd#123, interface stats: received=0, sent=0, dropped=0, active_time=29 secs
Jun 5 14:20:59 wily ntpd[3275]: Deleting interface #5 usb0, 192.168.42.109#123, interface stats: received=4, sent=5, dropped=0, active_time=29 secs
Jun 5 14:20:59 wily ntpd[3275]: 91.189.89.199 interface 192.168.42.109 -> (none)
Jun 5 14:20:59 wily ntpd[3275]: 212.43.246.10 interface 192.168.42.109 -> (none)
Jun 5 14:20:59 wily ntpd[3275]: 212.83.179.156 interface 192.168.42.109 -> (none)
Jun 5 14:20:59 wily ntpd[3275]: 91.121.169.20 interface 192.168.42.109 -> (none)
Jun 5 14:20:59 wily ntpd[3275]: 109.69.184.209 interface 192.168.42.109 -> (none)
Jun 5 14:20:59 wily ntpd[3275]: peers refreshed

There are traces throughout the wily's log of upstart errors. Might be systemd migration issue ?

Louis Bouchard (louis)
Changed in network-manager (Ubuntu):
status: New → Triaged
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.