Thursday, May 2, 2024
 Popular · Latest · Hot · Upcoming
2
rated 0 times [  2] [ 0]  / answers: 1 / hits: 2811  / 3 Years ago, sun, october 17, 2021, 5:45:15

I maintain a persistent 3G connection on a remote device using network manager. However, every so often, the link fails and then does not restart itself. I managed to identify an occurrence of this in my syslog, but honestly I'm not really sure what I'm looking at. It seems that the machine thinks the device has been unplugged, but there's no corresponding log entry for it actually being unplugged.



Would someone mind looking at the below syslog snip and guiding me in the right direction?



Oct 13 22:25:26 tracker pppd[1091]: LCP terminated by peer
Oct 13 22:25:26 tracker pppd[1091]: Connect time 206.7 minutes.
Oct 13 22:25:26 tracker pppd[1091]: Sent 203306 bytes, received 182777 bytes.
Oct 13 22:25:26 tracker pppd[1091]: Modem hangup
Oct 13 22:25:26 tracker pppd[1091]: Connection terminated.
Oct 13 22:25:26 tracker NetworkManager[333]: <info> (ttyUSB1): device state change: 8 -> 9 (reason 13)
Oct 13 22:25:26 tracker NetworkManager[333]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Oct 13 22:25:26 tracker NetworkManager[333]: <warn> Activation (ttyUSB1) failed.
Oct 13 22:25:26 tracker modem-manager[337]: <info> (ttyUSB1) closing serial port...
Oct 13 22:25:26 tracker NetworkManager[333]: <info> (ttyUSB1): device state change: 9 -> 3 (reason 0)
Oct 13 22:25:26 tracker NetworkManager[333]: <info> (ttyUSB1): deactivating device (reason: 0).
Oct 13 22:25:26 tracker kernel: [12441.840088] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Oct 13 22:25:26 tracker kernel: [12441.846744] ata1.00: BMDMA stat 0x66
Oct 13 22:25:26 tracker kernel: [12441.850446] ata1.00: failed command: WRITE DMA
Oct 13 22:25:26 tracker kernel: [12441.855020] ata1.00: cmd ca/00:02:c4:fb:5b/00:00:00:00:00/e0 tag 0 dma 1024 out
Oct 13 22:25:26 tracker kernel: [12441.855024] res 51/84:00:c4:fb:5b/00:00:00:00:00/e0 Emask 0x30 (host bus error)
Oct 13 22:25:26 tracker kernel: [12441.870623] ata1.00: status: { DRDY ERR }
Oct 13 22:25:26 tracker kernel: [12441.874708] ata1.00: error: { ICRC ABRT }
Oct 13 22:25:26 tracker kernel: [12441.878820] ata1: soft resetting link
Oct 13 22:25:26 tracker modem-manager[337]: <info> (ttyUSB1) serial port closed
Oct 13 22:25:26 tracker modem-manager[337]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
Oct 13 22:25:26 tracker modem-manager[337]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> connected)
Oct 13 22:25:26 tracker NetworkManager[333]: <warn> could not read ppp stats: No such device
Oct 13 22:25:26 tracker pppd[1091]: Exit.
Oct 13 22:25:26 tracker NetworkManager[333]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Oct 13 22:25:26 tracker NetworkManager[333]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Oct 13 22:25:26 tracker NetworkManager[333]: <info> disconnect failed: (32) The serial port is not open.
Oct 13 22:25:27 tracker kernel: [12442.048218] ata1.00: configured for UDMA/100
Oct 13 22:25:27 tracker kernel: [12442.048241] ata1: EH complete
Oct 13 22:25:27 tracker kernel: [12442.050941] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Oct 13 22:25:27 tracker kernel: [12442.057483] ata1.00: BMDMA stat 0x66
Oct 13 22:25:27 tracker kernel: [12442.061153] ata1.00: failed command: WRITE DMA
Oct 13 22:25:27 tracker kernel: [12442.065696] ata1.00: cmd ca/00:02:c4:fb:5b/00:00:00:00:00/e0 tag 0 dma 1024 out
Oct 13 22:25:27 tracker kernel: [12442.065699] res 51/84:00:c4:fb:5b/00:00:00:00:00/e0 Emask 0x30 (host bus error)
Oct 13 22:25:27 tracker kernel: [12442.081273] ata1.00: status: { DRDY ERR }
Oct 13 22:25:27 tracker kernel: [12442.085366] ata1.00: error: { ICRC ABRT }
Oct 13 22:25:27 tracker kernel: [12442.089488] ata1: soft resetting link
Oct 13 22:25:27 tracker kernel: [12442.260206] ata1.00: configured for UDMA/100
Oct 13 22:25:27 tracker kernel: [12442.260226] ata1: EH complete
Oct 13 22:25:27 tracker kernel: [12442.268296] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
Oct 13 22:25:27 tracker kernel: [12442.274829] ata1.00: BMDMA stat 0x66
Oct 13 22:25:27 tracker kernel: [12442.278480] ata1.00: failed command: WRITE DMA
Oct 13 22:25:27 tracker kernel: [12442.283022] ata1.00: cmd ca/00:02:c4:fb:5b/00:00:00:00:00/e0 tag 0 dma 1024 out
Oct 13 22:25:27 tracker kernel: [12442.283026] res 51/84:00:c4:fb:5b/00:00:00:00:00/e0 Emask 0x30 (host bus error)
Oct 13 22:25:27 tracker kernel: [12442.298605] ata1.00: status: { DRDY ERR }
Oct 13 22:25:27 tracker kernel: [12442.302693] ata1.00: error: { ICRC ABRT }
Oct 13 22:25:27 tracker kernel: [12442.306763] ata1: soft resetting link
Oct 13 22:25:27 tracker kernel: [12442.476225] ata1.00: configured for UDMA/100
Oct 13 22:25:27 tracker kernel: [12442.476248] ata1: EH complete
Oct 13 22:25:29 tracker NetworkManager[333]: <info> Activation (ttyUSB1) starting connection 'cdma'
Oct 13 22:25:29 tracker NetworkManager[333]: <info> (ttyUSB1): device state change: 3 -> 4 (reason 0)
Oct 13 22:25:29 tracker NetworkManager[333]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Oct 13 22:25:29 tracker NetworkManager[333]: <info> Activation (ttyUSB1) Stage 1 of 5 (Device Prepare) scheduled...
Oct 13 22:25:29 tracker NetworkManager[333]: <info> Activation (ttyUSB1) Stage 1 of 5 (Device Prepare) started...
Oct 13 22:25:29 tracker NetworkManager[333]: <info> Activation (ttyUSB1) Stage 1 of 5 (Device Prepare) complete.
Oct 13 22:25:30 tracker modem-manager[337]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> registered)
Oct 13 22:25:30 tracker modem-manager[337]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
Oct 13 22:25:30 tracker modem-manager[337]: <info> Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> registered)
Oct 13 22:25:30 tracker NetworkManager[333]: <warn> CDMA connection failed: (32) Sending command failed: device is not enabled
Oct 13 22:25:30 tracker NetworkManager[333]: <info> (ttyUSB1): device state change: 4 -> 9 (reason 0)
Oct 13 22:25:30 tracker NetworkManager[333]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Oct 13 22:25:30 tracker NetworkManager[333]: <info> Marking connection 'cdma' invalid.
Oct 13 22:25:30 tracker NetworkManager[333]: <warn> Activation (ttyUSB1) failed.
Oct 13 22:25:30 tracker NetworkManager[333]: <info> (ttyUSB1): device state change: 9 -> 3 (reason 0)
Oct 13 22:25:30 tracker NetworkManager[333]: <info> (ttyUSB1): deactivating device (reason: 0).
Oct 13 22:25:30 tracker NetworkManager[333]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)

More From » networking

 Answers
5

That's unfortunately how some 3G dongles work. If the serial port is closed, they essentially need to be reset back to a poweron mode. This might be possible to do using the "Enable mobile broadband" option in nm-applet by deselecting and selecting it again. Otherwise, it may need to be modeswitched again, in which case it may be simple to disconnect it from the computer and plug it in again (but if you really want to switch it manually, you will need to find out what parameters are passed to usb-modeswitch by udev, via /var/log/usb_modeswitch.log after you enable logging in /etc/usb_modeswitch.conf).



As a possible workaround, you may with to set persist in /etc/ppp/options (which should still get read when establishing the connection). This may help in keeping PPP up and avoid closing off the modem's ports.


[#43012] Monday, October 18, 2021, 3 Years  [reply] [flag answer]
Only authorized users can answer the question. Please sign in first, or register a free account.
tersle

Total Points: 342
Total Questions: 109
Total Answers: 99

Location: Kazakhstan
Member since Mon, Sep 26, 2022
2 Years ago
;