#19739: USB modem: option1 ttyUSB0: option_instat_callback: error -71
---------------------+----------------------------------------------------
Reporter: emusic | Owner: developers
Type: defect | Status: new
Priority: normal | Milestone:
Component: kernel | Version: Trunk
Resolution: | Keywords: usb,modem,e3272,option_instat_callback
---------------------+----------------------------------------------------
Comment (by emusic):
Attached a remote syslog server to collect messages at a time when the
error occurs (kernel error messages are issued several times per second so
device log cannot hold them for hours). See that the error occurs
suddenly, with no noticeable system/connection state changes:
----
May 30 00:00:54 dnsmasq-dhcp[1169]: DHCPREQUEST(br-lan) 192.168.1.138
00:1e:64:xx:xx:xx
May 30 00:00:54 dnsmasq-dhcp[1169]: DHCPACK(br-lan) 192.168.1.138
00:1e:64:xx:xx:xx nastya
May 30 00:01:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:01:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:01:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:01:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:11:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:11:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:11:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:11:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:15:09 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 00:21:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:21:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:21:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:21:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:26:34 dnsmasq-dhcp[1169]: DHCPREQUEST(br-lan) 192.168.1.139
94:db:c9:xx:xx:xx
May 30 00:26:34 dnsmasq-dhcp[1169]: DHCPACK(br-lan) 192.168.1.139
94:db:c9:xx:xx:xx P170EM
May 30 00:26:48 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 00:31:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:31:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:31:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:31:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:41:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:41:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:41:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:41:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:51:57 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:51:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:51:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:51:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 00:57:51 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 01:01:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:01:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:01:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:01:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:11:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:11:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:11:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:11:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:13:38 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 01:21:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:21:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:21:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:21:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:31:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:31:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:31:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:31:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:40:33 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 01:41:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:41:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:41:58 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:41:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:51:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:51:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:51:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:51:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 01:56:20 dnsmasq[1169]: possible DNS-rebind attack detected:
retracker.local
May 30 02:01:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:01:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:01:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:01:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:11:58 hostapd: wlan0: STA 00:e0:4c:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:11:58 hostapd: wlan0-1: STA 94:db:c9:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:11:58 hostapd: wlan0-1: STA 00:1e:64:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:11:59 hostapd: wlan0-1: STA 00:0f:60:xx:xx:xx WPA: group key
handshake completed (RSN)
May 30 02:14:19 kernel: [226371.410000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:19 kernel: [226372.000000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:19 kernel: [226371.610000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:19 kernel: [226371.810000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:20 kernel: [226372.200000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:20 kernel: [226372.390000] option1 ttyUSB0:
option_instat_callback: error -71
May 30 02:14:20 kernel: [226372.590000] option1 ttyUSB0:
option_instat_callback: error -71
----
A minute later, the interface becomes down and is never got up again
("error -71" messages are filtered out):
----
May 30 02:15:16 pppd[17374]: Connect time 489.5 minutes.
May 30 02:15:16 pppd[17374]: No response to 10 echo-requests
May 30 02:15:16 pppd[17374]: Serial link appears to be disconnected.
May 30 02:15:17 netifd: Interface ''wan1'' has lost the connection
May 30 02:15:17 pppd[17374]: Script /lib/netifd/ppp-down started (pid
5632)
May 30 02:15:16 netifd: Network device ''3g-wan1'' link is down
May 30 02:15:16 pppd[17374]: Sent 225140375 bytes, received 3068458996
bytes.
May 30 02:15:17 pppd[17374]: sent [LCP TermReq id=0x2 "Peer not
responding"]
May 30 02:15:17 pppd[17374]: Script /lib/netifd/ppp-down finished (pid
5632), status = 0x1
May 30 02:15:20 pppd[17374]: sent [LCP TermReq id=0x3 "Peer not
responding"]
May 30 02:15:23 pppd[17374]: Connection terminated.
May 30 02:15:24 pppd[17374]: Modem hangup
May 30 02:15:32 dnsmasq[1169]: no servers found in /tmp/resolv.conf.auto,
will retry
May 30 02:15:55 chat[5709]: report (CONNECT)
May 30 02:15:55 chat[5709]: expect (OK)
May 30 02:15:55 chat[5709]: send (AT&F^M)
May 30 02:15:55 chat[5709]: timeout set to 10 seconds
May 30 02:15:55 chat[5709]: abort on (ERROR)
May 30 02:15:55 chat[5709]: abort on (NO CARRIER)
May 30 02:15:55 chat[5709]: abort on (BUSY)
May 30 02:16:05 pppd[17374]: Script USE_APN=internet.mts.ru
DIALNUMBER=*99***1# /usr/sbin/chat -t5 -v -E -f /etc/chatscripts/3g.chat
finished (pid 5708), status = 0x3
May 30 02:16:05 pppd[17374]: Connect script failed
May 30 02:16:05 chat[5709]: alarm
May 30 02:16:05 chat[5709]: Failed
May 30 02:16:06 pppd[17374]: Exit.
May 30 02:16:06 netifd: Interface ''wan1'' is now down
May 30 02:16:06 netifd: Interface ''wan1'' is setting up now
May 30 02:16:07 netifd: wan1 (5755): uci: Entry not found
May 30 02:16:07 netifd: wan1 (5755): uci: Entry not found
May 30 02:16:13 Create PPP Connection:
May 30 02:16:13 pppd[5779]: pppd 2.4.7 started by root, uid 0
May 30 02:16:14 chat[5782]: abort on (NO CARRIER)
May 30 02:16:14 chat[5782]: expect (OK)
May 30 02:16:14 chat[5782]: send (AT&F^M)
May 30 02:16:14 chat[5782]: timeout set to 10 seconds
May 30 02:16:14 chat[5782]: report (CONNECT)
May 30 02:16:14 chat[5782]: abort on (BUSY)
May 30 02:16:14 chat[5782]: abort on (ERROR)
May 30 02:16:24 pppd[5779]: Connect script failed
May 30 02:16:24 pppd[5779]: Script USE_APN=internet.mts.ru
DIALNUMBER=*99***1# /usr/sbin/chat -t5 -v -E -f /etc/chatscripts/3g.chat
finished (pid 5781), status = 0x3
May 30 02:16:24 chat[5782]: Failed
May 30 02:16:24 chat[5782]: alarm
May 30 02:16:26 netifd: wan1 (5809): uci: Entry not found
May 30 02:16:26 netifd: wan1 (5809): killall: getsignal1: no process
killed
May 30 02:16:25 netifd: Interface ''wan1'' is setting up now
May 30 02:16:25 netifd: Interface ''wan1'' is now down
May 30 02:16:25 pppd[5779]: Exit.
----
The "high traffic" mode began at 01:00. About 3GB were downloaded before
the error.
--
Ticket URL: <https://dev.openwrt.org/ticket/19739#comment:3>
OpenWrt <http://openwrt.org>
Opensource Wireless Router Technology
_______________________________________________
openwrt-tickets mailing list
[email protected]
https://lists.openwrt.org/cgi-bin/mailman/listinfo/openwrt-tickets
