Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wwan0 interface not working under Stretch (no IPv4 address) #2544

Closed
jkuek opened this issue May 7, 2018 · 33 comments
Closed

wwan0 interface not working under Stretch (no IPv4 address) #2544

jkuek opened this issue May 7, 2018 · 33 comments

Comments

@jkuek
Copy link

@jkuek jkuek commented May 7, 2018

My RPI Model 2B is connected via USB to a 3G modem that uses the sierra_net driver.

Under Jessie, when the modem has a data connection, I get an IPv4 address on wwan0, and can access the Internet.

Under Stretch, it seems to try to assign an IPv6 address rather than an IPv4 address, but then reports the carrier as lost immediately:

May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: waiting for carrier
May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: carrier acquired
May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: IAID 66:a4:01:07
May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: adding address fe80::73c:641:6b89:d510
May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: carrier lost
May  7 00:12:04 raspberrypi dhcpcd[216]: wwan0: deleting address fe80::73c:641:6b89:d510

I don't believe my carrier is assigning an IP6 address, but it looks like the OS can't pick up the right IP?
If I manually run "dhclient wwan0" on Stretch then the right IPv4 address is shown, and the interface works as expected.

How can I resolve this issue?

@pelwell
Copy link
Contributor

@pelwell pelwell commented May 7, 2018

I believe there is a kernel command line option that may help - add ipv6.disable=1 to cmdline.txt (all in one line) and reboot.

@jkuek
Copy link
Author

@jkuek jkuek commented May 9, 2018

Here is my cmdline.txt:

dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=30ff3213-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait ipv6.disable=1

Adding that option did not resolve the issue, here is the relevant section from syslog:

May  9 02:23:22 raspberrypi avahi-daemon[210]: Failed to create IPv6 socket, proceeding in IPv4 only mode
May  9 02:23:22 raspberrypi systemd[1]: Started System Logging Service.
May  9 02:23:22 raspberrypi dhcpcd[215]: dev: loaded udev
May  9 02:23:22 raspberrypi avahi-daemon[210]: socket() failed: Address family not supported by protocol
May  9 02:23:22 raspberrypi avahi-daemon[210]: Network interface enumeration completed.
May  9 02:23:22 raspberrypi systemd[1]: Started Save/Restore Sound Card State.
May  9 02:23:22 raspberrypi avahi-daemon[210]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 2914948106.
May  9 02:23:22 raspberrypi systemd[1]: Started Disable WiFi if country not set.
May  9 02:23:22 raspberrypi dhcpcd[215]: no valid interfaces found
May  9 02:23:22 raspberrypi kernel: [   15.721276] usbcore: registered new interface driver usbserial
May  9 02:23:22 raspberrypi kernel: [   15.721408] usbcore: registered new interface driver usbserial_generic
May  9 02:23:22 raspberrypi kernel: [   15.721539] usbserial: USB Serial support registered for generic
May  9 02:23:22 raspberrypi kernel: [   15.736207] usbcore: registered new interface driver sierra
May  9 02:23:22 raspberrypi kernel: [   15.736348] usbserial: USB Serial support registered for Sierra USB modem
May  9 02:23:22 raspberrypi kernel: [   15.738556] sierra_net 1-1.4:1.7 wwan0: register 'sierra_net' at usb-20980000.usb-1.4, Sierra Wireless USB-to-WWAN Modem, d6:c0:66:a4:01:07
May  9 02:23:22 raspberrypi kernel: [   15.766899] sierra 1-1.4:1.0: Sierra USB modem converter detected
May  9 02:23:22 raspberrypi kernel: [   15.767195] usbcore: registered new interface driver sierra_net
May  9 02:23:22 raspberrypi kernel: [   15.769821] usb 1-1.4: Sierra USB modem converter now attached to ttyUSB0
May  9 02:23:22 raspberrypi kernel: [   15.770396] sierra 1-1.4:1.1: Sierra USB modem converter detected
May  9 02:23:22 raspberrypi kernel: [   15.796078] usb 1-1.4: Sierra USB modem converter now attached to ttyUSB1
May  9 02:23:22 raspberrypi kernel: [   15.796703] sierra 1-1.4:1.2: Sierra USB modem converter detected
May  9 02:23:22 raspberrypi kernel: [   15.804089] usb 1-1.4: Sierra USB modem converter now attached to ttyUSB2
May  9 02:23:22 raspberrypi kernel: [   15.836848] sierra 1-1.4:1.3: Sierra USB modem converter detected
May  9 02:23:22 raspberrypi kernel: [   15.838883] usb 1-1.4: Sierra USB modem converter now attached to ttyUSB3
May  9 02:23:23 raspberrypi dphys-swapfile[213]: Starting dphys-swapfile swapfile setup ...
May  9 02:23:23 raspberrypi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
May  9 02:23:23 raspberrypi systemd[1]: Started Login Service.
May  9 02:23:23 raspberrypi dphys-swapfile[213]: want /var/swap=100MByte, checking existing: keeping it
May  9 02:23:24 raspberrypi systemd[1]: Started Raise network interfaces.
May  9 02:23:24 raspberrypi raspi-config[203]: Checking if shift key is held down: No. Switching to ondemand scaling governor.
May  9 02:23:24 raspberrypi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
May  9 02:23:24 raspberrypi kernel: [   17.495436] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
May  9 02:23:24 raspberrypi dphys-swapfile[213]: done.
May  9 02:23:24 raspberrypi systemd[1]: Started LSB: Autogenerate and use a swap:
May  9 02:23:25 raspberrypi dhcpcd[215]: eth0: waiting for carrier
May  9 02:23:25 raspberrypi kernel: [   18.123848] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
May  9 02:23:25 raspberrypi dhcpcd[215]: eth0: carrier acquired
May  9 02:23:25 raspberrypi dhcpcd[215]: all: IPv6 kernel autoconf disabled
May  9 02:23:25 raspberrypi dhcpcd[215]: DUID 00:01:00:01:22:69:57:08:b8:27:eb:8f:13:fc
May  9 02:23:25 raspberrypi dhcpcd[215]: eth0: IAID eb:8f:13:fc
May  9 02:23:25 raspberrypi dhcpcd[215]: eth0: adding address fe80::5460:9f5e:11a8:4ad4
May  9 02:23:25 raspberrypi dhcpcd[215]: if_addaddress6: Operation not supported
May  9 02:23:25 raspberrypi systemd[1]: Reached target Sound Card.
May  9 02:23:25 raspberrypi dhcpcd[215]: eth0: soliciting a DHCP lease
May  9 02:23:25 raspberrypi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
May  9 02:23:26 raspberrypi systemd-udevd[112]: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
May  9 02:23:26 raspberrypi kernel: [   19.570191] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x41E1
May  9 02:23:26 raspberrypi dhcpcd[215]: all: IPv6 kernel autoconf disabled
May  9 02:23:26 raspberrypi dhcpcd[215]: wwan0: starting wpa_supplicant
May  9 02:23:26 raspberrypi dhcpcd-run-hooks[313]: wwan0: starting wpa_supplicant
May  9 02:23:27 raspberrypi dhcpcd[215]: wwan0: waiting for carrier
May  9 02:23:27 raspberrypi dhcpcd[215]: wwan0: carrier acquired
May  9 02:23:27 raspberrypi dhcpcd[215]: all: IPv6 kernel autoconf disabled
May  9 02:23:27 raspberrypi dhcpcd[215]: wwan0: IAID 66:a4:01:07
May  9 02:23:27 raspberrypi dhcpcd[215]: wwan0: adding address fe80::d1ba:2cda:bec4:e78b
May  9 02:23:27 raspberrypi dhcpcd[215]: if_addaddress6: Operation not supported
May  9 02:23:27 raspberrypi dhcpcd[215]: wwan0: carrier lost
May  9 02:23:29 raspberrypi dhcpcd[215]: eth0: offered 192.168.166.66 from 192.168.166.2
May  9 02:23:29 raspberrypi dhcpcd[215]: eth0: probing address 192.168.166.66/24
May  9 02:23:34 raspberrypi dhcpcd[215]: eth0: leased 192.168.166.66 for 86400 seconds
May  9 02:23:34 raspberrypi avahi-daemon[210]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.166.66.
May  9 02:23:34 raspberrypi avahi-daemon[210]: New relevant interface eth0.IPv4 for mDNS.
May  9 02:23:34 raspberrypi avahi-daemon[210]: Registering new address record for 192.168.166.66 on eth0.IPv4.
May  9 02:23:34 raspberrypi dhcpcd[215]: eth0: adding route to 192.168.166.0/24
May  9 02:23:34 raspberrypi dhcpcd[215]: eth0: adding default route via 192.168.166.254
May  9 02:23:34 raspberrypi dhcpcd[215]: forked to background, child pid 376
May  9 02:23:34 raspberrypi systemd[1]: Started dhcpcd on all interfaces.
May  9 02:23:34 raspberrypi systemd[1]: Reached target Network.

There are a few additional error messages but same result.

@macmpi
Copy link

@macmpi macmpi commented May 9, 2018

Did you disable new Predictable Network Interface naming, which is now default on Stretch?
Previous Jessie default names eth0, wlan0, etc... are no longer used (and configs relating to them become useless) unless you explicitly use those legacy names.
This can be done by either setting net.ifnames=0 in cmdline.txt, or ln -s /dev/null /etc/systemd/network/99-default.link

Alternatively, update your network config files and reference interfaces with their new predictable names.

@pelwell
Copy link
Contributor

@pelwell pelwell commented May 9, 2018

I think your IPv6 theory might be a red herring - that "carrier lost" message looks more significant.

  1. Are you able to capture an equivalent boot log from Jessie for comparison?
  2. How are you powering the Pi and the 3G dongle? Current draw is often at a peak during booting.
@jkuek
Copy link
Author

@jkuek jkuek commented May 11, 2018

The 3g modem is actually externally powered so I don't believe power is the problem here.

I tested some older Raspbian installs and with interesting results:

  • 2017-09-07-raspbian-stretch-lite.img = good (wwan0 has IP address)
  • 2017-11-29-raspbian-stretch-lite.img = bad (no IP address for wwan0)

And the version I provided partial logs for previously was the latest 2018-04-18-raspbian-stretch-lite which also fails to get an IP address.

I've attached the syslog from a fresh image for both of these versions. The line that seems to indicate something is wrong is "wwan0: carrier lost"

2017-09-07-raspbian-stretch-lite.log
2017-11-29-raspbian-stretch-lite.log

@pelwell
Copy link
Contributor

@pelwell pelwell commented May 11, 2018

That's about as narrow a time range (for images, at least) that we could have hoped for. 2017-09-07 is 4.9.41 (this firmware commit), while 2017-11.29 is 4.9.59 (here).

Considering that, the traces are quite different. Looking for wwan0 messages we get (old, good):

Sep  7 15:54:40 raspberrypi dhcpcd[250]: wwan0: waiting for carrier
Sep  7 15:54:40 raspberrypi kernel: [   21.042350] IPv6: ADDRCONF(NETDEV_UP): wwan0: link is not ready
Sep  7 15:54:41 raspberrypi systemd[1]: Started Raise network interfaces.
Sep  7 15:54:42 raspberrypi kernel: [   22.660424] IPv6: ADDRCONF(NETDEV_CHANGE): wwan0: link becomes ready
Sep  7 15:54:42 raspberrypi dhcpcd[250]: wwan0: carrier acquired
Sep  7 15:54:42 raspberrypi dhcpcd[250]: wwan0: adding address fe80::1e09:995:5f42:fa48
Sep  7 15:54:42 raspberrypi avahi-daemon[255]: Joining mDNS multicast group on interface wwan0.IPv6 with address fe80::1e09:995:5f42:fa48.
Sep  7 15:54:42 raspberrypi avahi-daemon[255]: New relevant interface wwan0.IPv6 for mDNS.
Sep  7 15:54:42 raspberrypi avahi-daemon[255]: Registering new address record for fe80::1e09:995:5f42:fa48 on wwan0.*.
Sep  7 15:54:43 raspberrypi dhcpcd[250]: DUID 00:01:00:01:21:44:28:43:26:46:ee:43:01:07
Sep  7 15:54:43 raspberrypi dhcpcd[250]: wwan0: IAID ee:43:01:07
Sep  7 15:54:43 raspberrypi dhcpcd[250]: wwan0: soliciting a DHCP lease
Sep  7 15:54:43 raspberrypi dhcpcd[250]: wwan0: soliciting an IPv6 router
Sep  7 15:54:43 raspberrypi dhcpcd[250]: wwan0: offered 100.113.23.172 from 100.113.23.253
Sep  7 15:54:43 raspberrypi dhcpcd[250]: wwan0: probing address 100.113.23.172/32

vs (new, bad):

Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: waiting for carrier
Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: carrier acquired
Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: IAID 17:fa:01:07
Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: adding address fe80::3cc3:cfbd:f6e4:82ec
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: Joining mDNS multicast group on interface wwan0.IPv6 with address fe80::3cc3:cfbd:f6e4:82ec.
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: New relevant interface wwan0.IPv6 for mDNS.
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: Registering new address record for fe80::3cc3:cfbd:f6e4:82ec on wwan0.*.
Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: carrier lost
Nov 29 02:37:27 raspberrypi dhcpcd[238]: wwan0: deleting address fe80::3cc3:cfbd:f6e4:82ec
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: Withdrawing address record for fe80::3cc3:cfbd:f6e4:82ec on wwan0.
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: Leaving mDNS multicast group on interface wwan0.IPv6 with address fe80::3cc3:cfbd:f6e4:82ec.
Nov 29 02:37:27 raspberrypi avahi-daemon[256]: Interface wwan0.IPv6 no longer relevant for mDNS.

If you've got the time, could you try upgrading the firmware of the older, working image:

$ sudo rpi-update a6b3e85

Obviously I'd like to know if it stills works after the update. Afterwards you can revert using:

$ sudo rpi-update b9becbb

If you are really keen, you could cross-check the result by downgrading the firmware of the newer image using the same hashes as before but in the reverse order, i.e. b9becbb to downgrade, then a6b3e85 to get back.

@jkuek
Copy link
Author

@jkuek jkuek commented May 21, 2018

Sorry for the delay, I've been on holiday.

OK the plot thickens...I have run the tests as you suggested, and here are the results:

Starting with 2017-09-07-raspbian-stretch-lite.img,

  1. Verify that wwan0 has an IP address (ifconfig wwan0) and that the interface works (ping -I wwan0 8.8.8.8)
  2. Update: sudo rpi-update a6b3e85
  3. Reboot: sudo reboot
  4. Verify kernel version (4.9.59)
  5. wwan0 still has an IP address and the interface can ping out.
  6. I updated again to the latest (sudo rpi-update), it went to 4.14.41
  7. sudo reboot again
  8. wwan0 still has an IP address and the interface can ping out.

Then I started again with a fresh 2017-11-29-raspbian-stretch-lite,

  1. Verify wwan0 does NOT have an IP address
  2. Update: sudo rpi-update b9becbb
  3. Reboot
  4. Verify kernel version (4.9.41)
  5. wwan0 does NOT have an IP address
  6. Looking at syslog, the same error occurs, where the carrier is "lost" a few seconds after it is "acquired"
  7. I restarted dhcpcd (sudo systemctl restart dhcpcd), but the problem remains.
@pelwell
Copy link
Contributor

@pelwell pelwell commented May 21, 2018

I think that lets the kernel off the hook.

@XECDesign Can you think of a change between the 2017-09-07 and 2017-11-29 releases that might have broken wwan/3G connectivity in this way?

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 21, 2018

Does putting nodev in dhcpcd.conf and restarting make any difference?

@jkuek
Copy link
Author

@jkuek jkuek commented May 21, 2018

adding nodev and restarting did not resolve the issue. I tried adding nodhcp6 as well, but still no luck.

In the bad cases, it looks like dhcpcd is trying to assign an IPv6 address to the wwan0 interface, when in fact, I don't think the wwan0 supports IPv6.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 22, 2018

Does this fix the issue?

wget http://archive.raspberrypi.org/debian/pool/main/d/dhcpcd5/dhcpcd5_6.10.1-1+rpi3_armhf.deb
sudo dpkg -i dhcpcd5_6.10.1-1+rpi3_armhf.deb
sudo systemctl restart dhcpcd5
@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 22, 2018

Before you try that, it would be interesting to know whether noipv6 in dhdpcd.conf makes any difference?

I am sure the culprit is the jump from dhcpcd 6.10.1 to 6.11.5, but checking whether ipv6 is a red herring may be useful information when determining why that jump breaks it.

@jkuek
Copy link
Author

@jkuek jkuek commented May 22, 2018

Adding noipv6 did not resolve the issue.

However downgrading to dhcpcd 6.10.1 and restarting dhcpcd did - the IP address is now present on wwan0 and the interface works as expected.

I also tried a fresh install of 2018-04-18-raspbian-stretch-lite, (where wwan0 doesn't have an IP out-of-the-box) and can confirm that the downgrade of dhcpcd works for that too.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 23, 2018

Thanks for confirming. It may be worth sending an email to the dhcpcd mailing list (bottom of the page here https://roy.marples.name/projects/dhcpcd).

Otherwise, I can take a look into later at some point.

@jkuek
Copy link
Author

@jkuek jkuek commented May 23, 2018

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 24, 2018

@spl237 This one's on us.

    --- a/if.c
    +++ b/if.c
    @@ -534,7 +534,7 @@
              /* We reserve the 100 range for virtual interfaces, if and when
               * we can work them out. */
              ifp->metric = 200 + ifp->index;
    -        if (if_getssid(ifp) != -1) {
    +        if (if_getssid(ifp) != -1 || *ifp->name == 'w') {
                  ifp->wireless = 1;
                  ifp->metric += 100;
              } 

From what I gather, that patch ends up treating 3G modems as wifi devices and starting wpa_supplicant, which doesn't make sense.

@spl237
Copy link

@spl237 spl237 commented May 24, 2018

OK, it's trivial to fix - I'll just patch to check for "wlan" rather than "w". Odd that the OP reports it works properly under jessie, though, as the code in our jessie release of dhcpcd has the same test for "w" as above. (I think it was missed out for a few months after we updated to stretch, but we put it in back in November last year.)

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 24, 2018

I think in jessie 3g modems showed up as serial devices and were handled through ppp rather than showing up as wwan devices, but I'm not sure.

Another user reported on the mailing list that everything worked fine for them on the latest version of dhcpcd until an upgrade broke it, which would probably be when we added this patch back in.

@macmpi
Copy link

@macmpi macmpi commented May 24, 2018

Out of curiosity: can't such kind of tests be done after actual interface types rather than after their names?
Interface naming conventions may change over time (i.e. Predictable naming or different defaults), so assuming types from names may lead to unexpected issues.

@spl237
Copy link

@spl237 spl237 commented May 24, 2018

This is a hack to deal with a badly-behaved driver for a particular wifi dongle, which does not correctly set internal flags and so is not identified as a wifi device. Hence in the case of this one device, we unfortunately do need to make an assumption based on its name...

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 24, 2018

That's something Roy pointed out as well. There's probably going to be some inconsistent behaviour if interfaces are renamed using udev rules or through persistent network interface naming.

@spl237
Copy link

@spl237 spl237 commented May 24, 2018

We could just tell anyone with an Edimax dongle to throw it away and buy another one! Or tell whoever wrote the driver / firmware for it to fix the problem and not support it in the meantime...

@pelwell
Copy link
Contributor

@pelwell pelwell commented May 24, 2018

If it is a driver issue we can patch it in raspberrypi/linux.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 24, 2018

If you're up for it, I think this is the driver (but it's worth double-checking):
https://github.com/raspberrypi/linux/tree/rpi-4.14.y/drivers/net/wireless/realtek/rtl8192cu

And Roy's description of the problem:

If the operation of getting the SSID returns -1 that means that there was an error. Even if not associated and not instructed to associate, the call will succeed. Every wireless card must support getting and setting SSID as a minium and only wireless cards do this.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented May 24, 2018

A version of dhcpcd with that patch removed to help confirm that that was the problem:
dhcpcd5_6.11.5-1+rpt6~test_armhf.deb.gz

@jkuek
Copy link
Author

@jkuek jkuek commented May 25, 2018

I can confirm that dhcpcd5_6.11.5-1+rpt5_armhf.deb does not work, but dhcpcd5_6.11.5-1.rpt6.test_armhf.deb does!

@JamesH65
Copy link
Contributor

@JamesH65 JamesH65 commented Jun 26, 2018

@spl237 Have you any idea which internal flags are being incorrectly set in the driver? I'm happy to fix this up if I know what to fix! Or has it already been done? Not sure of exact status of this one.

@jkuek
Copy link
Author

@jkuek jkuek commented Sep 5, 2018

@JamesH65 An interim fix is to modify the patch (#2544 (comment)) to check for interfaces starting with "wl" (eg. wlan0) rather than just "w"

@JamesH65
Copy link
Contributor

@JamesH65 JamesH65 commented Sep 5, 2018

@spl237 ISTR us discussing this? Cannot remember what the result was.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented Sep 5, 2018

We couldn't find a dongle that exhibits the behaviour the patch was added to fix. It's probably better to revert the patch anyway and then if the problem resurfaces again, fix it properly in the driver.

@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented Sep 10, 2018

The latest version of dhcpd in apt has the fix, so this can probably be closed.

@JamesH65
Copy link
Contributor

@JamesH65 JamesH65 commented Sep 10, 2018

Thanks all, esp. @XECDesign

@JamesH65 JamesH65 closed this Sep 10, 2018
@XECDesign
Copy link
Contributor

@XECDesign XECDesign commented Sep 10, 2018

Looks like this has indeed found the faulty driver:
https://www.raspberrypi.org/forums/viewtopic.php?p=1363824#p1363824

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants