Huawei ME909s-120 modem goes offline and disappears

Wed Dec 11 14:38:57 UTC 2019

Hey,

Here's the interesting part of the log.

We trigger disconnection of the context using CGACT=0, the modem replies OK:

> <debug> [1576037518.692459] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
> <info>  [1576037518.692526] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
> <debug> [1576037518.693010] Sending PDP context deactivation in secondary port...
> <debug> [1576037518.693052] (ttyUSB3) device open count is 2 (open)
> <debug> [1576037518.693148] (ttyUSB3): --> 'AT+CGACT=0,1<CR>'
> <debug> [1576037518.707274] (ttyUSB3): <-- '<CR><LF>^RSSI: 16<CR><LF><CR><LF>^HCSQ: "LTE",41,25,51,4<CR><LF>'
> <debug> [1576037518.707538] 3GPP signal quality: 51
> <debug> [1576037518.707696] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (51)
> <debug> [1576037518.708110] (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> <debug> [1576037518.708318] Reopening data port (ttyUSB1)...
> <debug> [1576037518.708351] (ttyUSB1) reopening port (2)
> <debug> [1576037518.708362] (ttyUSB1) device open count is 1 (close)
> <debug> [1576037518.708373] (ttyUSB1) device open count is 0 (close)
> <debug> [1576037518.708388] (ttyUSB1) closing serial port...
> <debug> [1576037518.708403] (ttyUSB1): port now disconnected
> <debug> [1576037518.708441] (ttyUSB1) serial port closed

NM triggers reconnection of the module using DBus Simple.Connect() method....

> <debug> [1576037518.708462] (ttyUSB3) device open count is 1 (close)
> <info>  [1576037518.776560] Simple connect started...
> <debug> [1576037518.776587]    PIN: unspecified
> <debug> [1576037518.776597]    Operator ID: unspecified
> <debug> [1576037518.776607]    Allowed roaming: yes
> <debug> [1576037518.776617]    APN: web.vodafone.de
> <debug> [1576037518.776628]    IP family: ipv4
> <debug> [1576037518.776651]    Allowed authentication: none, pap, chap, mschap, mschapv2, eap
> <debug> [1576037518.776683]    User: unspecified
> <debug> [1576037518.776693]    Password: unspecified
> <info>  [1576037518.776702] Simple connect state (4/8): Wait to get fully enabled
> <debug> [1576037519.709825] (ttyUSB1) opening serial port...
> <debug> [1576037519.710402] (ttyUSB1): setting up baudrate: 57600
> <debug> [1576037519.710444] (ttyUSB1): no flow control explicitly requested for device
> <debug> [1576037519.710484] (ttyUSB1): port attributes not fully set
> <debug> [1576037519.710585] (ttyUSB1) device open count is 1 (open)
> <debug> [1576037519.710611] (ttyUSB1) device open count is 2 (open)

Here we can see how the disconnection logic hasn't finished yet, as
the port is still being flashed.

> <debug> [1576037519.710684] Flashing data port (ttyUSB1)...
> <debug> [1576037519.710740] (ttyUSB1): port attributes not fully set
> <debug> [1576037520.287636] (ttyUSB1) device open count is 3 (open)

But at the same time, we attempt to use the same TTY due to the
ongoing connection status checks, which are only disabled once
'disconnected' (not while 'disconnecting')....

> <debug> [1576037520.287804] (ttyUSB1): --> 'AT+CGACT?<CR>'
> <debug> [1576037520.711067] (ttyUSB1) device open count is 2 (close)
> <debug> [1576037520.711127] (ttyUSB1): running init sequence...
> <debug> [1576037520.711231] PDP disconnection already sent
> <debug> [1576037520.711263] Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'

At this point the disconnection logic has finished, but the CGACT?
that got in the middle never gets a reply. After this, all commands we
attempt to send to ttyUSB1 end up timing out, and after 10 consecutive
timeouts, MM removes the modem from its logic because it cannot use
the primary control port.

Now, in this specific case, given that the connection status command
is triggered *during* the disconnection process, I believe this could
be caused by MM.
I believe that we could either remove those connection checks also if
bearer state goes to "disconnecting", or otherwise keep them removed
only when "disconnected" but make sure they are a no-op while
disconnecting. I think the latter would be a bit safer, as we wouldn't
need to care for when the disconnection procedure fails.

Let me prepare a patch to see if we can avoid this.

> <info>  [1576037520.711379] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> enabled)
> <info>  [1576037520.711564] Simple connect state (5/8): Register
> <debug> [1576037520.711648] Launching automatic network registration...
> <debug> [1576037520.711706] (ttyUSB1) device open count is 3 (open)
> <debug> [1576037520.712647] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
> <debug> [1576037520.712758] Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (umts -> unknown)
> <debug> [1576037520.712791] Periodic signal checks disabled
> <warn>  [1576037523.655707] checking if connected failed: Couldn't check current list of active PDP contexts: Sending command failed: 'Resource temporarily unavailable'
> <debug> [1576037523.655803] (ttyUSB1) device open count is 2 (close)
> <debug> [1576037523.655893] (ttyUSB1): --> 'ATE0<CR>'
> <debug> [1576037525.880202] (ttyUSB3): <-- '<CR><LF>+CGREG: 2<CR><LF>'
> <debug> [1576037525.880558] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <info>  [1576037525.880611] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
> <debug> [1576037525.880794] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <info>  [1576037525.880981] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> searching)
> <debug> [1576037525.882605] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037526.909448] (ttyUSB3): <-- '<CR><LF>^SRVST: 1<CR><LF>'
> <warn>  [1576037527.005141] (tty/ttyUSB1) at port timed out 2 consecutive times
> <debug> [1576037527.005306] (ttyUSB1): --> 'ATV1<CR>'
> <warn>  [1576037530.346891] (tty/ttyUSB1) at port timed out 3 consecutive times
> <debug> [1576037530.347068] (ttyUSB1): --> 'AT+CMEE=1<CR>'
> <warn>  [1576037533.677720] (tty/ttyUSB1) at port timed out 4 consecutive times
> <debug> [1576037533.677845] (ttyUSB1): --> 'ATX4<CR>'
> <debug> [1576037534.291548] (ttyUSB3): <-- '<CR><LF>^SRVST: 0<CR><LF>'
> <debug> [1576037534.292084] (ttyUSB3): <-- '<CR><LF>+CGREG: 0<CR><LF>'
> <debug> [1576037534.292259] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <info>  [1576037534.292288] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
> <debug> [1576037534.292409] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037534.292530] Bearer not allowed to connect, not registered in 3GPP network
> <debug> [1576037534.292570] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037534.292664] (ttyUSB3): <-- '<CR><LF>+CGREG: 2<CR><LF>'
> <debug> [1576037534.292797] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <info>  [1576037534.292821] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
> <debug> [1576037534.292891] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037534.292978] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <warn>  [1576037537.037186] (tty/ttyUSB1) at port timed out 5 consecutive times
> <debug> [1576037537.037353] (ttyUSB1): --> 'AT&C1<CR>'
> <debug> [1576037537.241255] (ttyUSB3): <-- '<CR><LF>^RSSI: 17<CR><LF>'
> <debug> [1576037537.241450] 3GPP signal quality: 54
> <debug> [1576037537.241691] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (54)
> <debug> [1576037537.241950] (ttyUSB3): <-- '<CR><LF>^HCSQ: "LTE",42,23,0,252<CR><LF>'
> <debug> [1576037537.284239] (ttyUSB3): <-- '<CR><LF>^RSSI: 17<CR><LF>'
> <debug> [1576037537.284424] 3GPP signal quality: 54
> <debug> [1576037537.284615] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (54)
> <debug> [1576037537.284900] (ttyUSB3): <-- '<CR><LF>^HCSQ: "LTE",42,23,41,252<CR><LF>'
> <debug> [1576037540.380133] (ttyUSB3): <-- '<CR><LF>^SRVST: 1<CR><LF>'
> <warn>  [1576037540.383831] (tty/ttyUSB1) at port timed out 6 consecutive times
> <debug> [1576037540.383972] (ttyUSB1): --> 'AT+COPS=0<CR>'
> <warn>  [1576037543.717511] (tty/ttyUSB1) at port timed out 7 consecutive times
> <debug> [1576037543.717659] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <debug> [1576037543.717704] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <info>  [1576037543.717737] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
> <debug> [1576037543.717906] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037543.718071] Bearer not allowed to connect, not registered in 3GPP network
> <debug> [1576037543.718160] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037543.718632] (ttyUSB1) device open count is 1 (close)
> <info>  [1576037543.760549] Simple connect started...
> <debug> [1576037543.760578]    PIN: unspecified
> <debug> [1576037543.760589]    Operator ID: unspecified
> <debug> [1576037543.760598]    Allowed roaming: yes
> <debug> [1576037543.760608]    APN: web.vodafone.de
> <debug> [1576037543.760619]    IP family: ipv4
> <debug> [1576037543.760645]    Allowed authentication: none, pap, chap, mschap, mschapv2, eap
> <debug> [1576037543.760657]    User: unspecified
> <debug> [1576037543.760667]    Password: unspecified
> <info>  [1576037543.760676] Simple connect state (4/8): Wait to get fully enabled
> <info>  [1576037543.760724] Simple connect state (5/8): Register
> <debug> [1576037543.760771] Launching automatic network registration...
> <debug> [1576037543.760803] (ttyUSB1) device open count is 2 (open)
> <debug> [1576037543.760868] (ttyUSB1): --> 'AT+COPS=0<CR>'
> <warn>  [1576037547.093772] (tty/ttyUSB1) at port timed out 8 consecutive times
> <debug> [1576037547.093924] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <debug> [1576037547.093970] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <debug> [1576037547.094496] (ttyUSB1) device open count is 1 (close)
> <info>  [1576037547.127470] Simple connect started...
> <debug> [1576037547.127505]    PIN: unspecified
> <debug> [1576037547.127515]    Operator ID: unspecified
> <debug> [1576037547.127525]    Allowed roaming: yes
> <debug> [1576037547.127563]    APN: web.vodafone.de
> <debug> [1576037547.127574]    IP family: ipv4
> <debug> [1576037547.127599]    Allowed authentication: none, pap, chap, mschap, mschapv2, eap
> <debug> [1576037547.127612]    User: unspecified
> <debug> [1576037547.127621]    Password: unspecified
> <info>  [1576037547.127631] Simple connect state (4/8): Wait to get fully enabled
> <info>  [1576037547.127680] Simple connect state (5/8): Register
> <debug> [1576037547.127726] Launching automatic network registration...
> <debug> [1576037547.127760] (ttyUSB1) device open count is 2 (open)
> <debug> [1576037547.127829] (ttyUSB1): --> 'AT+COPS=0<CR>'
> <debug> [1576037548.012429] (ttyUSB3): <-- '<CR><LF>^RSSI: 15<CR><LF>'
> <debug> [1576037548.012577] 3GPP signal quality: 48
> <debug> [1576037548.012811] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (48)
> <debug> [1576037548.013084] (ttyUSB3): <-- '<CR><LF>^HCSQ: "LTE",38,28,41,6<CR><LF>'
> <debug> [1576037548.013926] (ttyUSB3): <-- '<CR><LF>^SRVST: 0<CR><LF>'
> <debug> [1576037548.014556] (ttyUSB3): <-- '<CR><LF>+CGREG: 0<CR><LF>'
> <debug> [1576037548.015548] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <debug> [1576037548.015760] (ttyUSB3): <-- '<CR><LF>+CGREG: 2<CR><LF>'
> <debug> [1576037548.015994] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <info>  [1576037548.016032] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
> <debug> [1576037548.016187] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037548.016382] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037549.042472] (ttyUSB3): <-- '<CR><LF>^SRVST: 1<CR><LF>'
> <warn>  [1576037550.465411] (tty/ttyUSB1) at port timed out 9 consecutive times
> <debug> [1576037550.465552] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <debug> [1576037550.465596] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <info>  [1576037550.465629] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
> <debug> [1576037550.465794] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037550.465961] Bearer not allowed to connect, not registered in 3GPP network
> <debug> [1576037550.466047] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037550.466507] (ttyUSB1) device open count is 1 (close)
> <info>  [1576037550.497815] Simple connect started...
> <debug> [1576037550.497845]    PIN: unspecified
> <debug> [1576037550.497855]    Operator ID: unspecified
> <debug> [1576037550.497865]    Allowed roaming: yes
> <debug> [1576037550.497875]    APN: web.vodafone.de
> <debug> [1576037550.497887]    IP family: ipv4
> <debug> [1576037550.497910]    Allowed authentication: none, pap, chap, mschap, mschapv2, eap
> <debug> [1576037550.497921]    User: unspecified
> <debug> [1576037550.497930]    Password: unspecified
> <info>  [1576037550.497939] Simple connect state (4/8): Wait to get fully enabled
> <info>  [1576037550.497991] Simple connect state (5/8): Register
> <debug> [1576037550.498039] Launching automatic network registration...
> <debug> [1576037550.498072] (ttyUSB1) device open count is 2 (open)
> <debug> [1576037550.498139] (ttyUSB1): --> 'AT+COPS=0<CR>'
> <debug> [1576037553.597340] (ttyUSB3): <-- '<CR><LF>^RSSI: 9<CR><LF>'
> <debug> [1576037553.597492] 3GPP signal quality: 29
> <debug> [1576037553.597730] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (29)
> <debug> [1576037553.598148] (ttyUSB3): <-- '<CR><LF>^HCSQ: "LTE",27,17,41,12<CR><LF>'
> <debug> [1576037553.599112] (ttyUSB3): <-- '<CR><LF>^SRVST: 0<CR><LF>'
> <debug> [1576037553.599497] (ttyUSB3): <-- '<CR><LF>+CGREG: 0<CR><LF>'
> <debug> [1576037553.599749] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <debug> [1576037553.600526] (ttyUSB3): <-- '<CR><LF>+CGREG: 2<CR><LF>'
> <debug> [1576037553.600777] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <info>  [1576037553.600818] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
> <debug> [1576037553.601020] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037553.601255] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <error> [1576037553.833904] (tty/ttyUSB1) at port timed out 10 consecutive times, marking modem '/org/freedesktop/ModemManager1/Modem/0' as invalid
> <debug> [1576037553.834088] building consolidated registration state: cs 'idle', ps 'searching', eps 'unknown' --> 'searching'
> <debug> [1576037553.834136] building consolidated registration state: cs 'idle', ps 'idle', eps 'unknown' --> 'idle'
> <info>  [1576037553.834166] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
> <debug> [1576037553.834335] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037553.834503] Bearer not allowed to connect, not registered in 3GPP network
> <debug> [1576037553.834587] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Tracking area code: '0', Cell ID: '0')
> <debug> [1576037553.835064] (ttyUSB1) device open count is 1 (close)
> <debug> [1576037553.836368] Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
> <debug> [1576037553.836454] [device /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4] unexported modem from path '/org/freedesktop/ModemManager1/Modem/0'
> <debug> [1576037553.837184] Extended signal information reporting disabled
> <debug> [1576037553.838127] (ttyUSB4) forced to close port
> <debug> [1576037553.838238] (ttyUSB1) device open count is 0 (close)
> <debug> [1576037553.838276] (ttyUSB1) closing serial port...
> <debug> [1576037553.838872] (ttyUSB1) serial port closed
> <debug> [1576037553.839016] (ttyUSB1) forced to close port
> <debug> [1576037553.839098] (ttyUSB3) device open count is 0 (close)
> <debug> [1576037553.839127] (ttyUSB3) closing serial port...
> <debug> [1576037553.839670] (ttyUSB3) serial port closed
> <debug> [1576037553.839940] (ttyUSB3) forced to close port
> <debug> [1576037553.840024] Modem (Huawei) '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4' completely disposed
>
>
> Thanks
> Bruno

-- 
Aleksander
https://aleksander.es