desktop-packages team mailing list archive

Thread
Date
[Bug 1405289] [NEW] network-manager reports usb link as disconnected

To: desktop-packages@xxxxxxxxxxxxxxxxxxx
From: Gilles Pietri <contact+ubuntu@xxxxxxxxxxxx>
Date: Tue, 23 Dec 2014 22:01:52 -0000
Reply-to: Bug 1405289 <1405289@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When I plug my Motorola XT910 (Razr Max) as USB, with connection sharing
on USB enabled on the phone, network-manager sees it, but reports it as
disconnected. If I activate the usb0 interface manually (ifconfig /
dhclient), it works, flawlessly.

I set network manager to log debug info, this is what I get, once the device is plugged in (MAC & S/N removed) :
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.827268] usb 1-2: new high-speed USB device number 10 using xhci_hcd
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.278667] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x1002
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955942] usb 1-2: New USB device found, idVendor=22b8, idProduct=431c
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955945] usb 1-2: New USB device strings: Mfr=2, Product=3, SerialNumber=4
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955947] usb 1-2: Product: XT910
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955949] usb 1-2: Manufacturer: Motorola
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955950] usb 1-2: SerialNumber: XXXXX
Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.957736] rndis_host 1-2:1.0 usb0: register 'rndis_host' at usb-0000:00:14.0-2, RNDIS device, xx:xx:xx:xx:xx:xx
Dec 23 20:15:00 gilles-M3800 mtp-probe: checking bus 1, device 10: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2"
Dec 23 20:15:00 gilles-M3800 mtp-probe: bus: 1, device: 10 was not an MTP device
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0/net/usb0, iface: usb0)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0/net/usb0, iface: usb0): no ifupdown configuration found.
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301139] [nm-udev-manager.c:563] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'usb0'
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <warn> failed to allocate link cache: (-26) Protocol mismatch
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301528] [nm-device-ethernet.c:1624] supports_ethtool_carrier_detect(): ethtool is supported
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301609] [nm-device-wired.c:313] constructor(): (usb0): kernel ifindex 5
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): carrier is OFF
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301765] [nm-device-ethernet.c:261] constructor(): (usb0): kernel ifindex 5
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.302205] [nm-device-ethernet.c:485] update_initial_hw_address(): (usb0): read initial MAC address 62:A4:06:B5:C8:73
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): new Ethernet device (driver: 'rndis_host' ifindex: 5)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/3
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.302928] [nm-device.c:5333] nm_device_set_managed(): (usb0): now managed
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): bringing up device.
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): carrier now ON (device state 20)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303239] [nm-device.c:5272] nm_device_queue_state(): (usb0): queued state change to disconnected (id 657)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): preparing device.
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): deactivating device (reason 'managed') [2]
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303338] [nm-device.c:5295] nm_device_queued_state_clear(): (usb0): clearing queued state transition (id 657)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303355] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/usb0/accept_ra' to '0'
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303371] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/usb0/use_tempaddr' to '0'
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303380] [nm-device-ethernet.c:384] _set_hw_addr(): (usb0): no MAC address change needed
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303416] [nm-system.c:1404] nm_system_iface_flush_routes(): (usb0): flushing routes ifindex 5 family INET (2)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303468] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/32
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303475] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/8
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303480] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.1/32
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303485] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.255.255.255/32
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303536] [nm-system.c:194] sync_addresses(): (usb0): syncing addresses (family 2)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303586] [nm-manager.c:4022] connectivity_changed(): connectivity checking indicates NONE
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> NetworkManager state is now DISCONNECTED
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303637] [nm-device.c:5161] nm_device_state_changed(): (usb0): device is available, will transition to DISCONNECTED
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303644] [nm-device.c:5272] nm_device_queue_state(): (usb0): queued state change to disconnected (id 659)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303700] [nm-manager.c:1395] system_create_virtual_devices(): creating virtual devices...
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304257] [nm-udev-manager.c:216] recheck_killswitches(): WiFi rfkill switch rfkill2 state now 1/0
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304307] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x11043
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304373] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 1 flags 0x10049
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304381] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 2 flags 0x1003
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304388] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x11043
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304488] [nm-device.c:5230] queued_set_state(): (usb0): running queued state change to disconnected (id 659)
Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
[...]

I have no idea how the "connected" state is detected on cdc_ether, so I
assume network-manager simply doesn't know if it's up or not. On the
phone side, it's "up as can be", but maybe something is not reported as
it should. It's possible. I didn't find a way to fake the connected
state on NM's side.

This is on a updated Ubuntu 14.10, running either the 3.16 kernel from Ubuntu, or the latest mainline one (3.18).
% NetworkManager --version
0.9.8.8
package is 0.9.8.8-0ubuntu28.

Maybe udev is involved as well, so udev is 208-8ubuntu8.1

** Affects: network-manager (Ubuntu)
     Importance: Undecided
         Status: New


** Tags: utopic

-- 
You received this bug notification because you are a member of Desktop
Packages, which is subscribed to network-manager in Ubuntu.
https://bugs.launchpad.net/bugs/1405289

Title:
  network-manager reports usb link as disconnected

Status in network-manager package in Ubuntu:
  New

Bug description:
  When I plug my Motorola XT910 (Razr Max) as USB, with connection
  sharing on USB enabled on the phone, network-manager sees it, but
  reports it as disconnected. If I activate the usb0 interface manually
  (ifconfig / dhclient), it works, flawlessly.

  I set network manager to log debug info, this is what I get, once the device is plugged in (MAC & S/N removed) :
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.827268] usb 1-2: new high-speed USB device number 10 using xhci_hcd
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.278667] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x1002
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955942] usb 1-2: New USB device found, idVendor=22b8, idProduct=431c
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955945] usb 1-2: New USB device strings: Mfr=2, Product=3, SerialNumber=4
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955947] usb 1-2: Product: XT910
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955949] usb 1-2: Manufacturer: Motorola
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.955950] usb 1-2: SerialNumber: XXXXX
  Dec 23 20:15:00 gilles-M3800 kernel: [ 3959.957736] rndis_host 1-2:1.0 usb0: register 'rndis_host' at usb-0000:00:14.0-2, RNDIS device, xx:xx:xx:xx:xx:xx
  Dec 23 20:15:00 gilles-M3800 mtp-probe: checking bus 1, device 10: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2"
  Dec 23 20:15:00 gilles-M3800 mtp-probe: bus: 1, device: 10 was not an MTP device
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]:    SCPlugin-Ifupdown: devices added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0/net/usb0, iface: usb0)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]:    SCPlugin-Ifupdown: device added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0/net/usb0, iface: usb0): no ifupdown configuration found.
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301139] [nm-udev-manager.c:563] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'usb0'
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <warn> failed to allocate link cache: (-26) Protocol mismatch
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301528] [nm-device-ethernet.c:1624] supports_ethtool_carrier_detect(): ethtool is supported
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301609] [nm-device-wired.c:313] constructor(): (usb0): kernel ifindex 5
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): carrier is OFF
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.301765] [nm-device-ethernet.c:261] constructor(): (usb0): kernel ifindex 5
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.302205] [nm-device-ethernet.c:485] update_initial_hw_address(): (usb0): read initial MAC address 62:A4:06:B5:C8:73
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): new Ethernet device (driver: 'rndis_host' ifindex: 5)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): exported as /org/freedesktop/NetworkManager/Devices/3
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.302928] [nm-device.c:5333] nm_device_set_managed(): (usb0): now managed
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): bringing up device.
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): carrier now ON (device state 20)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303239] [nm-device.c:5272] nm_device_queue_state(): (usb0): queued state change to disconnected (id 657)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): preparing device.
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): deactivating device (reason 'managed') [2]
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303338] [nm-device.c:5295] nm_device_queued_state_clear(): (usb0): clearing queued state transition (id 657)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303355] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/usb0/accept_ra' to '0'
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303371] [NetworkManagerUtils.c:637] nm_utils_do_sysctl(): sysctl: setting '/proc/sys/net/ipv6/conf/usb0/use_tempaddr' to '0'
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303380] [nm-device-ethernet.c:384] _set_hw_addr(): (usb0): no MAC address change needed
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303416] [nm-system.c:1404] nm_system_iface_flush_routes(): (usb0): flushing routes ifindex 5 family INET (2)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303468] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/32
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303475] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.0/8
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303480] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.0.0.1/32
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303485] [nm-netlink-utils.c:356] dump_route():   route idx 1 family INET (2) addr 127.255.255.255/32
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303536] [nm-system.c:194] sync_addresses(): (usb0): syncing addresses (family 2)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303586] [nm-manager.c:4022] connectivity_changed(): connectivity checking indicates NONE
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> NetworkManager state is now DISCONNECTED
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303637] [nm-device.c:5161] nm_device_state_changed(): (usb0): device is available, will transition to DISCONNECTED
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303644] [nm-device.c:5272] nm_device_queue_state(): (usb0): queued state change to disconnected (id 659)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.303700] [nm-manager.c:1395] system_create_virtual_devices(): creating virtual devices...
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304257] [nm-udev-manager.c:216] recheck_killswitches(): WiFi rfkill switch rfkill2 state now 1/0
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304307] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x11043
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304373] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 1 flags 0x10049
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304381] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 2 flags 0x1003
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304388] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 5 flags 0x11043
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <debug> [1419362100.304488] [nm-device.c:5230] queued_set_state(): (usb0): running queued state change to disconnected (id 659)
  Dec 23 20:15:00 gilles-M3800 NetworkManager[1284]: <info> (usb0): device state change: unavailable -> disconnected (reason 'none') [20 30 0]
  [...]

  I have no idea how the "connected" state is detected on cdc_ether, so
  I assume network-manager simply doesn't know if it's up or not. On the
  phone side, it's "up as can be", but maybe something is not reported
  as it should. It's possible. I didn't find a way to fake the connected
  state on NM's side.

  This is on a updated Ubuntu 14.10, running either the 3.16 kernel from Ubuntu, or the latest mainline one (3.18).
  % NetworkManager --version
  0.9.8.8
  package is 0.9.8.8-0ubuntu28.

  Maybe udev is involved as well, so udev is 208-8ubuntu8.1

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/network-manager/+bug/1405289/+subscriptions
Follow ups

[Bug 1405289] [NEW] network-manager reports usb link as disconnected
From: Gilles Pietri, 2014-12-23
References

[Bug 1405289] [NEW] network-manager reports usb link as disconnected
From: Gilles Pietri, 2014-12-23