Disconnect every 638-643 seconds...

[Falias]

EM7565, USB2.0 M.2 Enclosure, Verizon, Linux...

I'm getting a very consistent disconnect about every 640 seconds, after which it reconnects pretty much instantly without further issue.

I have no idea where to even start looking... anyone able to help?

Thanks

Code: Select all

May 24 22:38:56 aname NetworkManager[604]: <info>  [1558751936.2263] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 22:49:34 aname NetworkManager[604]: <info>  [1558752574.0478] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:00:13 aname NetworkManager[604]: <info>  [1558753213.2146] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:10:52 aname NetworkManager[604]: <info>  [1558753852.7961] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:21:30 aname NetworkManager[604]: <info>  [1558754490.1385] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:32:09 aname NetworkManager[604]: <info>  [1558755129.2085] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:42:49 aname NetworkManager[604]: <info>  [1558755769.7185] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 24 23:53:33 aname NetworkManager[604]: <info>  [1558756413.2688] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:04:11 aname NetworkManager[604]: <info>  [1558757051.7319] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:14:51 aname NetworkManager[604]: <info>  [1558757691.2172] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:25:31 aname NetworkManager[604]: <info>  [1558758331.8874] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:36:13 aname NetworkManager[604]: <info>  [1558758973.9973] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:46:55 aname NetworkManager[604]: <info>  [1558759615.2119] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 00:57:36 aname NetworkManager[604]: <info>  [1558760256.8419] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May 25 01:08:18 aname NetworkManager[604]: <info>  [1558760898.6960] device (cdc-wdm2): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')

Code: Select all

Manufacturer: Sierra Wireless, Incorporated
Model: EM7565U
Revision: SWI9X50C_01.08.04.00 dbb5d0 jenkins 2018/08/21 21:40:11
IMEI: -
IMEI SV:  8
FSN: -
+GCAP: +CGSM
OK
AT!IMPREF?!IMPREF: 
 preferred fw version:    01.08.04.00 preferred carrier name:  GENERIC
 preferred config name:   GENERIC_002.011_000 current fw version:      01.08.04.00
 current carrier name:    GENERIC current config name:     GENERIC_002.011_000
OK
AT!IMAGE?TYPE SLOT STATUS LRU FAILURES UNIQUE_ID   BUILD_ID
FW   1    GOOD   2   0 0      ?_?         01.08.04.00_?FW   2    GOOD   1   0 0      ?_?         01.07.02.00_?
FW   3    FOTA   0   0 0                  FW   4    EMPTY  0   0 0                  
Max FW images: 4
Active FW image is at slot 1
TYPE SLOT STATUS LRU FAILURES UNIQUE_ID   BUILD_ID
PRI  FF   GOOD   0   0 0      002.008_002 01.07.02.00_ATT
PRI  FF   GOOD   0   0 0      002.011_000 01.08.04.00_GENERIC
Max PRI images: 50

[JimHelms]

Are you using the OEM power cable that comes with the M.2 adapter enclosure. If so, this is most likely your problem.

[Falias]

I'm not, I got the recommended power cable with it.

I ran ModemManager and NetworkManager with the debug options; the first event during a disconnect is:

Code: Select all

...

... which seems pretty worthless as far as troubleshooting goes.

NetworkManager reports the change slightly after, then reports that it's fully connected again at 1558988480.0478. (The downtime is less than 1.5 seconds, but it causes all current sessions and transfers to hang, so it makes it unusable.)

It seems like it must be software related because of how consistent it is... some operation is getting scheduled every 10.5 minutes, and then waiting to run... I have literally hundreds of disconnects now all following that pattern - some a few seconds more than the original batch, but all definitely 640+-10.

Thanks again for any help!

Code: Select all

...

[Falias]

All hail the rubber ducky.

dhcpcd was verifying its leases every 10 minutes (+30 second timeout) and removing the modem's ip address when no resolvers responded. I'm not sure why the first message in the system log is the modem sending a message saying that it's deactivated rather than dhcpcd reporting the change... and for that matter, how the modem actually detects that it lost the connection since it shouldn't actually deal with the ip layer...? (Also, it would be nice if these modems/4g networks actually used dhcp like every other network.)

So... for anyone having this issue in the future - either exclude the modem interface from dhcpcd, or just switch to NetworkManager's built in dhcp client (systemd-networkd) since NetworkManager/ModemManager are the ones assigning the modem's ip in the first place.

Thanks again for looking.