2011-04-07 02:11:50

by Gottfried Haider

[permalink] [raw]
Subject: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

Hello,

I am using an Android phone connected over USB to connect to the
internet. Something in -rc2 broke this, as I am not getting
connections through NetworkManager anymore (it doesn't receive a
DHCPOFFER anymore and times out).

This does work on the -rc1 kernel and is 100% reproducible here (same
USB port, rebooting the phone between tries).


dmesg is about the same in both cases (the usb-storage is here as the
phone frist tries to act as a mass storage device after connect and I
have to manually activate a checkbox to switch to tethering
functionality):

[ 235.150385] usb 1-3: new high speed USB device number 3 using ehci_hcd
[ 235.320523] scsi2 : usb-storage 1-3:1.0
[ 235.801209] usb 1-3: USB disconnect, device number 3
[ 236.200390] usb 1-3: new high speed USB device number 4 using ehci_hcd
[ 236.452982] usbcore: registered new interface driver cdc_ether
[ 236.473241] rndis_host 1-3:1.0: usb0: register 'rndis_host' at
usb-0000:00:12.2-3, RNDIS device, 06:0f:e2:6a:61:cd
[ 236.474151] usbcore: registered new interface driver rndis_host
[ 236.487433] usbcore: registered new interface driver rndis_wlan
[ 246.850094] usb0: no IPv6 routers present


lspci is at http://sukzessiv.net/x120e , let me know if you need any more info.

cheers,
gohai



Below the full NetworkMonitor output of the working (-rc1) case and
below the failing (-rc2) one. I noticed the different ifindex in line
two, but other than that I don't see any difference except the
obviously missing DHCPOFFER.

-- begin working (-rc1) --
NetworkManager[1958]: <info> (usb0): carrier is OFF
NetworkManager[1958]: <info> (usb0): new Ethernet device (driver:
'rndis_host' ifindex: 5)
NetworkManager[1958]: <info> (usb0): exported as
/org/freedesktop/NetworkManager/Devices/2
NetworkManager[1958]: <info> (usb0): now managed
NetworkManager[1958]: <info> (usb0): device state change: 1 -> 2 (reason 2)
NetworkManager[1958]: <info> (usb0): bringing up device.
NetworkManager[1958]: <info> (usb0): preparing device.
NetworkManager[1958]: <info> (usb0): deactivating device (reason: 2).
NetworkManager[1958]: <info> Added default wired connection 'Auto
usb0' for /sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0
NetworkManager[1958]: <info> (usb0): carrier now ON (device state 2)
NetworkManager[1958]: <info> (usb0): device state change: 2 -> 3 (reason 40)
NetworkManager[1958]: SCPlugin-Ifupdown: devices added (path:
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0, iface:
usb0)
NetworkManager[1958]: SCPlugin-Ifupdown: device added (path:
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0, iface:
usb0): no ifupdown configuration found.
NetworkManager[1958]: <info> Activation (usb0) starting connection 'Auto usb0'
NetworkManager[1958]: <info> (usb0): device state change: 3 -> 4 (reason 0)
NetworkManager[1958]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) scheduled...
NetworkManager[1958]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) started...
NetworkManager[1958]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) scheduled...
NetworkManager[1958]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) complete.
NetworkManager[1958]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) starting...
NetworkManager[1958]: <info> (usb0): device state change: 4 -> 5 (reason 0)
NetworkManager[1958]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) successful.
NetworkManager[1958]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) scheduled.
NetworkManager[1958]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) complete.
NetworkManager[1958]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) started...
NetworkManager[1958]: <info> (usb0): device state change: 5 -> 7 (reason 0)
NetworkManager[1958]: <info> Activation (usb0) Beginning DHCPv4
transaction (timeout in 45 seconds)
NetworkManager[1958]: <info> dhclient started with pid 2030
NetworkManager[1958]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) complete.
Internet Systems Consortium DHCP Client 4.1.1-P1
Copyright 2004-2010 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

NetworkManager[1958]: <info> (usb0): DHCPv4 state changed nbi -> preinit
Listening on LPF/usb0/3e:fd:8f:24:d4:25
Sending on LPF/usb0/3e:fd:8f:24:d4:25
Sending on Socket/fallback
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 3
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 5
DHCPOFFER of 192.168.42.47 from 192.168.42.129
DHCPREQUEST of 192.168.42.47 on usb0 to 255.255.255.255 port 67
DHCPACK of 192.168.42.47 from 192.168.42.129
NetworkManager[1958]: <info> (usb0): DHCPv4 state changed preinit -> bound
NetworkManager[1958]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Get) scheduled...
NetworkManager[1958]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Get) started...
NetworkManager[1958]: <info> address 192.168.42.47
NetworkManager[1958]: <info> prefix 24 (255.255.255.0)
NetworkManager[1958]: <info> gateway 192.168.42.129
NetworkManager[1958]: <info> hostname 'x120e'
NetworkManager[1958]: <info> nameserver '192.168.42.129'
bound to 192.168.42.47 -- renewal in 1587 seconds.
NetworkManager[1958]: <info> Scheduling stage 5
NetworkManager[1958]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) scheduled...
NetworkManager[1958]: <info> Done scheduling stage 5
NetworkManager[1958]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Get) complete.
NetworkManager[1958]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) started...
NetworkManager[1958]: <info> (usb0): device state change: 7 -> 8 (reason 0)
NetworkManager[1958]: <info> Policy set 'Auto usb0' (usb0) as default
for IPv4 routing and DNS.
NetworkManager[1958]: <info> Activation (usb0) successful, device activated.
NetworkManager[1958]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) complete.
-- end working (-rc1) --

-- begin fail (-rc2) --
NetworkManager[2541]: <info> (usb0): carrier is OFF
NetworkManager[2541]: <info> (usb0): new Ethernet device (driver:
'rndis_host' ifindex: 6)
NetworkManager[2541]: <info> (usb0): exported as
/org/freedesktop/NetworkManager/Devices/2
NetworkManager[2541]: <info> (usb0): now managed
NetworkManager[2541]: <info> (usb0): device state change: 1 -> 2 (reason 2)
NetworkManager[2541]: <info> (usb0): bringing up device.
NetworkManager[2541]: <info> (usb0): preparing device.
NetworkManager[2541]: <info> (usb0): deactivating device (reason: 2).
NetworkManager[2541]: <info> Added default wired connection 'Auto
usb0' for /sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0
NetworkManager[2541]: <info> (usb0): carrier now ON (device state 2)
NetworkManager[2541]: <info> (usb0): device state change: 2 -> 3 (reason 40)
NetworkManager[2541]: SCPlugin-Ifupdown: devices added (path:
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0, iface:
usb0)
NetworkManager[2541]: SCPlugin-Ifupdown: device added (path:
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-3/1-3:1.0/net/usb0, iface:
usb0): no ifupdown configuration found.
NetworkManager[2541]: <info> Activation (usb0) starting connection 'Auto usb0'
NetworkManager[2541]: <info> (usb0): device state change: 3 -> 4 (reason 0)
NetworkManager[2541]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) scheduled...
NetworkManager[2541]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) started...
NetworkManager[2541]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) scheduled...
NetworkManager[2541]: <info> Activation (usb0) Stage 1 of 5 (Device
Prepare) complete.
NetworkManager[2541]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) starting...
NetworkManager[2541]: <info> (usb0): device state change: 4 -> 5 (reason 0)
NetworkManager[2541]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) successful.
NetworkManager[2541]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) scheduled.
NetworkManager[2541]: <info> Activation (usb0) Stage 2 of 5 (Device
Configure) complete.
NetworkManager[2541]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) started...
NetworkManager[2541]: <info> (usb0): device state change: 5 -> 7 (reason 0)
NetworkManager[2541]: <info> Activation (usb0) Beginning DHCPv4
transaction (timeout in 45 seconds)
NetworkManager[2541]: <info> dhclient started with pid 2609
NetworkManager[2541]: <info> Activation (usb0) Stage 3 of 5 (IP
Configure Start) complete.
Internet Systems Consortium DHCP Client 4.1.1-P1
Copyright 2004-2010 Internet Systems Consortium.
All rights reserved.
For info, please visit https://www.isc.org/software/dhcp/

NetworkManager[2541]: <info> (usb0): DHCPv4 state changed nbi -> preinit
Listening on LPF/usb0/06:eb:ae:9f:5d:5d
Sending on LPF/usb0/06:eb:ae:9f:5d:5d
Sending on Socket/fallback
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 3
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 4
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 5
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 13
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 18
DHCPDISCOVER on usb0 to 255.255.255.255 port 67 interval 14
NetworkManager[2541]: <warn> (usb0): DHCPv4 request timed out.
NetworkManager[2541]: <info> (usb0): canceled DHCP transaction, DHCP
client pid 2609
NetworkManager[2541]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Timeout) scheduled...
NetworkManager[2541]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Timeout) started...
NetworkManager[2541]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) scheduled...
NetworkManager[2541]: <info> Activation (usb0) Stage 4 of 5 (IP4
Configure Timeout) complete.
NetworkManager[2541]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) started...
NetworkManager[2541]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) failed (no IP configuration found)
NetworkManager[2541]: <info> (usb0): device state change: 7 -> 9 (reason 5)
NetworkManager[2541]: <info> Marking connection 'Auto usb0' invalid.
NetworkManager[2541]: <warn> Activation (usb0) failed.
NetworkManager[2541]: <info> Activation (usb0) Stage 5 of 5 (IP
Configure Commit) complete.
NetworkManager[2541]: <info> (usb0): device state change: 9 -> 3 (reason 0)
NetworkManager[2541]: <info> (usb0): deactivating device (reason: 0).
-- end fail (-rc2) --


2011-04-07 16:38:48

by Greg KH

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

On Thu, Apr 07, 2011 at 04:11:27AM +0200, Gottfried Haider wrote:
> Hello,
>
> I am using an Android phone connected over USB to connect to the
> internet. Something in -rc2 broke this, as I am not getting
> connections through NetworkManager anymore (it doesn't receive a
> DHCPOFFER anymore and times out).
>
> This does work on the -rc1 kernel and is 100% reproducible here (same
> USB port, rebooting the phone between tries).

Any chance you can run 'git bisect' to narrow down the problem to the
offending change?

thanks,

greg k-h

2011-04-07 16:40:56

by Greg KH

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

On Thu, Apr 07, 2011 at 09:39:48AM -0700, Greg KH wrote:
> On Thu, Apr 07, 2011 at 04:11:27AM +0200, Gottfried Haider wrote:
> > Hello,
> >
> > I am using an Android phone connected over USB to connect to the
> > internet. Something in -rc2 broke this, as I am not getting
> > connections through NetworkManager anymore (it doesn't receive a
> > DHCPOFFER anymore and times out).
> >
> > This does work on the -rc1 kernel and is 100% reproducible here (same
> > USB port, rebooting the phone between tries).
>
> Any chance you can run 'git bisect' to narrow down the problem to the
> offending change?

I just tested this myself and can confirm it doesn't work, but I will
not have the time to run 'git bisect' until next week as I'm on the road
:(

thanks,

greg k-h

2011-04-08 02:18:34

by Gottfried Haider

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

>> This does work on the -rc1 kernel and is 100% reproducible here (same
>> USB port, rebooting the phone between tries).
>
> Any chance you can run 'git bisect' to narrow down the problem to the
> offending change?

Unfortunately I only have this x120e netbook-type machine available
for testing and building at the moment, so it would probably take me a
long time.

Gottfried

2011-04-08 03:29:12

by Huajun Li

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

2011/4/8 Gottfried Haider <[email protected]>:
>>> This does work on the -rc1 kernel and is 100% reproducible here (same
>>> USB port, rebooting the phone between tries).
>>
>> Any chance you can run 'git bisect' to narrow down the problem to the
>> offending change?
>
> Unfortunately I only have this x120e netbook-type machine available
> for testing and building at the moment, so it would probably take me a
> long time.
>
> Gottfried
> --
> To unsubscribe from this list: send the line "unsubscribe linux-usb" in
> the body of a message to [email protected]
> More majordomo info at ?http://vger.kernel.org/majordomo-info.html
>

Hi,
I found the new added mask code 'FLAG_POINTTOPOINT' overlapped
'FLAG_MULTI_PACKET' in include/linux/usb/usbnet.h, this maybe
caused logic issue in rx_process(). I create a patch for this, but
have no such a device to test it, could you have a try? thanks.

Thanks,
--huajun


[PATCH] Clean up mask code overlaps in driver_info of usbnet

Signed-off-by: Huajun Li <[email protected]>
---
include/linux/usb/usbnet.h | 4 ++--
1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/include/linux/usb/usbnet.h b/include/linux/usb/usbnet.h
index 3c7329b..0e18550 100644
--- a/include/linux/usb/usbnet.h
+++ b/include/linux/usb/usbnet.h
@@ -103,8 +103,8 @@ struct driver_info {
* Indicates to usbnet, that USB driver accumulates multiple IP packets.
* Affects statistic (counters) and short packet handling.
*/
-#define FLAG_MULTI_PACKET 0x1000
-#define FLAG_RX_ASSEMBLE 0x2000 /* rx packets may span >1 frames */
+#define FLAG_MULTI_PACKET 0x2000
+#define FLAG_RX_ASSEMBLE 0x4000 /* rx packets may span >1 frames */

/* init device ... can sleep, or cause probe() failure */
int (*bind)(struct usbnet *, struct usb_interface *);
--
1.7.4.1

2011-04-08 03:31:42

by Gottfried Haider

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

> ? I found the new added mask code 'FLAG_POINTTOPOINT' overlapped
> 'FLAG_MULTI_PACKET' in ? ?include/linux/usb/usbnet.h, this maybe
> caused logic issue in rx_process(). I create a patch for this, but
> have no such a device to test it, could you have a try? thanks.

Will try the patch tomorrow morning and report back.

Gottfried


> [PATCH] ? ?Clean up mask code overlaps in driver_info of usbnet
>
> Signed-off-by: ?Huajun Li <[email protected]>
> ---
> ?include/linux/usb/usbnet.h | ? ?4 ++--
> ?1 files changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/include/linux/usb/usbnet.h b/include/linux/usb/usbnet.h
> index 3c7329b..0e18550 100644
> --- a/include/linux/usb/usbnet.h
> +++ b/include/linux/usb/usbnet.h
> @@ -103,8 +103,8 @@ struct driver_info {
> ?* Indicates to usbnet, that USB driver accumulates multiple IP packets.
> ?* Affects statistic (counters) and short packet handling.
> ?*/
> -#define FLAG_MULTI_PACKET ? ? ?0x1000
> -#define FLAG_RX_ASSEMBLE ? ? ? 0x2000 ?/* rx packets may span >1 frames */
> +#define FLAG_MULTI_PACKET ? ? ?0x2000
> +#define FLAG_RX_ASSEMBLE ? ? ? 0x4000 ?/* rx packets may span >1 frames */
>
> ? ? ? ?/* init device ... can sleep, or cause probe() failure */
> ? ? ? ?int ? ? (*bind)(struct usbnet *, struct usb_interface *);

2011-04-08 13:01:32

by Gottfried Haider

[permalink] [raw]
Subject: Re: [Regression] USB tethering does not work anymore in 2.6.29-rc2 (rndis_host, does not receive DHCP offer anymore)

> Hi,
> ? I found the new added mask code 'FLAG_POINTTOPOINT' overlapped
> 'FLAG_MULTI_PACKET' in ? ?include/linux/usb/usbnet.h, this maybe
> caused logic issue in rx_process(). I create a patch for this, but
> have no such a device to test it, could you have a try? thanks.

That patch fixes it, thanks!

Gottfried