WAN Interface failed to start

Hi,

i'm using OpenWrt 18.06.5 r7897-9d401013fc on ZBT-WE826 (16M). For internet connection, i'm using the built in EC25 LTE modem. Built in means an internal card which is attached via mini pci (using usb interface)).

The router is installed in a external measurement station. To save energy, the device is only turned on for 2 hours per day.

I observed, that the device sometimes problems to establish an internet connection, since the WAN interface fails to start. The log tells me, that the wan interace becomes down, short time after start.

Does any body know the reason for this behavior and could help me? I assume, i'm using a bad/wrong configuration.

network.wan=interface
network.wan.proto='3g'
network.wan.service='umts'
network.wan.ipv6='auto'
network.wan.apn='internet.t-mobile'
network.wan.username='tm'
network.wan.password='tm'
network.wan.device='/dev/ttyUSB2'
network.wan.dialnumber='*99***1#'

Failed start:

Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: tunnel
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: Network device
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: bridge
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: veth
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: macvlan
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: 8021ad
Fri Mar  6 18:58:47 2020 user.notice : Added device handler type: 8021q
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.646436] 8021q: adding VLAN 0 to HW filter on device eth0
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.658932] br-lan: port 1(eth0.1) entered blocking state
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.664547] br-lan: port 1(eth0.1) entered disabled state
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.670432] device eth0.1 entered promiscuous mode
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.675547] device eth0 entered promiscuous mode
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.685032] br-lan: port 1(eth0.1) entered blocking state
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.690601] br-lan: port 1(eth0.1) entered forwarding state
Fri Mar  6 18:58:53 2020 kern.info kernel: [   35.696576] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'lan' is enabled
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'lan' is setting up now
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'lan' is now up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'loopback' is enabled
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'loopback' is setting up now
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'loopback' is now up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'wan' is setting up now
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'wan6' is enabled
Fri Mar  6 18:58:53 2020 daemon.notice netifd: bridge 'br-lan' link is up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'lan' has link connectivity
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Network device 'eth0' link is up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: VLAN 'eth0.1' link is up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Network device 'lo' link is up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'loopback' has link connectivity
Fri Mar  6 18:58:53 2020 daemon.notice netifd: VLAN 'eth0.2' link is up
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'wan6' has link connectivity
Fri Mar  6 18:58:53 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Fri Mar  6 18:58:54 2020 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Fri Mar  6 18:58:54 2020 daemon.err odhcp6c[1306]: Failed to send RS (Address not available)
Fri Mar  6 18:58:54 2020 daemon.err odhcp6c[1306]: Failed to send DHCPV6 message to ff02::1:2 (Address not available)
Fri Mar  6 18:58:54 2020 kern.info kernel: [   36.644804] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Fri Mar  6 18:58:55 2020 daemon.notice netifd: Interface 'wan' is now down
Fri Mar  6 18:58:57 2020 user.notice mac80211: Failed command: iw phy phy0 set antenna all all
Fri Mar  6 18:58:57 2020 daemon.notice netifd: radio0 (1271): command failed: Not supported (-122)
Fri Mar  6 18:58:57 2020 user.notice mac80211: Failed command: iw phy phy0 set distance 0
Fri Mar  6 18:58:58 2020 daemon.err block: /dev/mtdblock5 is already mounted on /rom
Fri Mar  6 18:58:58 2020 daemon.err block: /dev/mtdblock6 is already mounted on /overlay
Fri Mar  6 18:58:58 2020 daemon.err block: /dev/sda1 is already mounted on /mnt/RouterUsbDrive
Fri Mar  6 18:58:59 2020 daemon.err hostapd: Configuration file: /var/run/hostapd-phy0.conf
Fri Mar  6 18:58:59 2020 kern.info kernel: [   42.202362] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Fri Mar  6 18:58:59 2020 kern.info kernel: [   42.238688] br-lan: port 2(wlan0) entered blocking state
Fri Mar  6 18:58:59 2020 kern.info kernel: [   42.244126] br-lan: port 2(wlan0) entered disabled state
Fri Mar  6 18:58:59 2020 kern.info kernel: [   42.250023] device wlan0 entered promiscuous mode
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/network reload dependency on /etc/config/dhcp
Fri Mar  6 18:59:00 2020 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Mar  6 18:59:00 2020 daemon.err hostapd: Using interface wlan0 with hwaddr 78:a3:51:69:4d:7c and ssid "ExxonValdez"
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/network reload dependency on /etc/config/radvd
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/wireless reload dependency on /etc/config/network
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/luci-splash
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/qos
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/miniupnpd
Fri Mar  6 18:59:00 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/sqm
Fri Mar  6 18:59:01 2020 user.notice ucitrack: Setting up /etc/config/dhcp reload dependency on /etc/config/odhcpd
Fri Mar  6 18:59:01 2020 daemon.info dnsmasq[948]: exiting on receipt of SIGTERM
Fri Mar  6 18:59:01 2020 daemon.info dnsmasq[1689]: started, version 2.80 cachesize 150
Fri Mar  6 18:59:01 2020 daemon.info dnsmasq[1689]: DNS service limited to local subnets
Fri Mar  6 18:59:01 2020 daemon.info dnsmasq[1689]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCP
 no-conntrack no-ipset no-auth no-DNSSEC no-ID loop-detect inotify dumpfile
Fri Mar  6 18:59:01 2020 daemon.info dnsmasq-dhcp[1689]: DHCP, IP range 192.168.8.100 -- 192.168.8.249, lease time 12h

Successful start:

Thu Mar  5 19:58:41 2020 user.notice : Added device handler type: macvlan
Thu Mar  5 19:58:41 2020 user.notice : Added device handler type: 8021ad
Thu Mar  5 19:58:41 2020 user.notice : Added device handler type: 8021q
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.655545] 8021q: adding VLAN 0 to HW filter on device eth0
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.676611] br-lan: port 1(eth0.1) entered blocking state
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.682139] br-lan: port 1(eth0.1) entered disabled state
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.688266] device eth0.1 entered promiscuous mode
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.693221] device eth0 entered promiscuous mode
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.729831] br-lan: port 1(eth0.1) entered blocking state
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.735422] br-lan: port 1(eth0.1) entered forwarding state
Thu Mar  5 19:58:46 2020 kern.info kernel: [   36.741330] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'lan' is enabled
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'lan' is setting up now
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'lan' is now up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'loopback' is enabled
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'loopback' is setting up now
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'loopback' is now up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'wan' is setting up now
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'wan6' is enabled
Thu Mar  5 19:58:46 2020 daemon.notice netifd: bridge 'br-lan' link is up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'lan' has link connectivity
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Network device 'eth0' link is up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: VLAN 'eth0.1' link is up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Network device 'lo' link is up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'loopback' has link connectivity
Thu Mar  5 19:58:46 2020 daemon.notice netifd: VLAN 'eth0.2' link is up
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'wan6' has link connectivity
Thu Mar  5 19:58:46 2020 daemon.notice netifd: Interface 'wan6' is setting up now
Thu Mar  5 19:58:47 2020 user.notice firewall: Reloading firewall due to ifup of lan (br-lan)
Thu Mar  5 19:58:47 2020 daemon.err odhcp6c[1410]: Failed to send RS (Address not available)
Thu Mar  5 19:58:47 2020 kern.info kernel: [   37.718125] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Thu Mar  5 19:58:49 2020 daemon.err block: /dev/mtdblock5 is already mounted on /rom
Thu Mar  5 19:58:49 2020 user.notice mac80211: Failed command: iw phy phy0 set antenna all all
Thu Mar  5 19:58:49 2020 daemon.err block: /dev/mtdblock6 is already mounted on /overlay
Thu Mar  5 19:58:49 2020 daemon.err block: /dev/sda1 is already mounted on /mnt/RouterUsbDrive
Thu Mar  5 19:58:49 2020 daemon.notice netifd: radio0 (1354): command failed: Not supported (-122)
Thu Mar  5 19:58:49 2020 user.notice mac80211: Failed command: iw phy phy0 set distance 0
Thu Mar  5 19:58:50 2020 daemon.notice pppd[1587]: pppd 2.4.7 started by root, uid 0
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/network reload dependency on /etc/config/dhcp
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/network reload dependency on /etc/config/radvd
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/wireless reload dependency on /etc/config/network
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/luci-splash
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/qos
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/miniupnpd
Thu Mar  5 19:58:51 2020 user.notice ucitrack: Setting up /etc/config/firewall reload dependency on /etc/config/sqm
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: abort on (BUSY)
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: abort on (NO CARRIER)
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: abort on (ERROR)
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: report (CONNECT)
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: timeout set to 10 seconds
Thu Mar  5 19:58:51 2020 local2.info chat[1653]: send (AT&F^M)
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: expect (OK)
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: AT&F^M^M
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: OK
Thu Mar  5 19:58:52 2020 local2.info chat[1653]:  -- got it
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: send (ATE1^M)
Thu Mar  5 19:58:52 2020 user.notice ucitrack: Setting up /etc/config/dhcp reload dependency on /etc/config/odhcpd
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: expect (OK)
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: ^M
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: ATE1^M^M
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: OK
Thu Mar  5 19:58:52 2020 local2.info chat[1653]:  -- got it
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: send (AT+CGDCONT=1,"IP","internet.t-mobile"^M)
Thu Mar  5 19:58:52 2020 local2.info chat[1653]: timeout set to 30 seconds

I remember I helped someone else with a similar problem recently.
A couple of ideas are to add some delay in the interface to let the device start up first.
Otherwise to load the module from the beginning.
Finally some thoughts, no immediately connected to your problem, are to try a different protocol, other than 3G, since you have the LTE modem.

Hi trendy,

thanks for your fast reply. I tried before a connection via QMI Mode, but get the same problem.

I'm new in OpenWrt, so i don't know, where to add the delay. Do you have more information, how i can do this?

Thanks in advance,

Marcel

uci set network.wan.delay=15
uci commit network
service network restart