Huawei ME909s-120 modem goes offline and disappears

Mon Dec 16 08:59:31 UTC 2019

Hey,

>
> > Do you have debug logs of the retest?
>
> I was able to reproduce the problem again with debug logs on. I have attached the logs.
>
> Regarding the patch implementation on balenaOS, I received two answers from balena:
>
> We didn’t backport the patch, it applied on 1.10.6 with no changes.
> I’ve been in contact with the OS team, and we’ve raised a new issue for this moving ModemManager to 1.12.2: https://github.com/balena-os/meta-balena/issues/1775
> Unfortunately I can’t give you an ETA for this but if you follow the attached ticket you should see the changes as progress is made.
>
> So my understanding is that I have re-tested your patch applied on top of MM 1.10.6.

Here are the new relevant logs.

The NM logs show how pppd detects the port as being disconnected:

rcvd [LCP TermReq id=0x2]
LCP terminated by peer
nm-pppd-plugin-Message: 20:35:05.384: nm-ppp-plugin: status 8 / phase 'network'
Connect time 720.5 minutes.
Sent 0 bytes, received 4 bytes.

NM at that point kills pppd and then notifies MM, in that order. That
part is working ok I believe:

<debug> [1576269305.4461] kill child process 'pppd' (5769): wait for
process to terminate after sending SIGTERM (15) (send SIGKILL in 1500
milliseconds)...
<debug> [1576269305.4466] modem-broadband[ttyUSB1]: notifying
ModemManager about the modem disconnection

The disconnection request comes to MM, and we run AT+CGACT=0,1 to
disconnect context #1. We send that command on the secondary port and
the modem replies OK.

<debug> [1576269305.448567] Disconnecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
<info>  [1576269305.448632] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
disconnecting)
<debug> [1576269305.449065] Sending PDP context deactivation in
secondary port...
<debug> [1576269305.449093] (ttyUSB3) device open count is 2 (open)
<debug> [1576269305.449167] (ttyUSB3): --> 'AT+CGACT=0,1<CR>'
<debug> [1576269305.464964] (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'

We fully close the ttyUSB1 at this point, and we wait 1 full second
with the port closed completely:

<debug> [1576269305.465193] Reopening data port (ttyUSB1)...
<debug> [1576269305.465219] (ttyUSB1) reopening port (2)
<debug> [1576269305.465230] (ttyUSB1) device open count is 1 (close)
<debug> [1576269305.465241] (ttyUSB1) device open count is 0 (close)
<debug> [1576269305.465257] (ttyUSB1) closing serial port...
<debug> [1576269305.465272] (ttyUSB1): port now disconnected
<debug> [1576269305.465317] (ttyUSB1) serial port closed
<debug> [1576269305.465337] (ttyUSB3) device open count is 1 (close)

We now get a new connection request, but we do not send anything to
the modem yet as the disconnection is ongoing.

<info>  [1576269305.535348] Simple connect started...
<debug> [1576269305.535385]    PIN: unspecified
<debug> [1576269305.535395]    Operator ID: unspecified
<debug> [1576269305.535405]    Allowed roaming: yes
<debug> [1576269305.535415]    APN: web.vodafone.de
<debug> [1576269305.535426]    IP family: ipv4
<debug> [1576269305.535451]    Allowed authentication: none, pap,
chap, mschap, mschapv2, eap
<debug> [1576269305.535463]    User: unspecified
<debug> [1576269305.535473]    Password: unspecified
<info>  [1576269305.535482] Simple connect state (4/8): Wait to get
fully enabled

After 1s, we reopen the port and flash it (setting baudrate to 0 for 1
full second)

<debug> [1576269306.466655] (ttyUSB1) opening serial port...
<debug> [1576269306.467097] (ttyUSB1): setting up baudrate: 57600
<debug> [1576269306.467174] (ttyUSB1): no flow control explicitly
requested for device
<debug> [1576269306.467223] (ttyUSB1): port attributes not fully set
<debug> [1576269306.467355] (ttyUSB1) device open count is 1 (open)
<debug> [1576269306.467383] (ttyUSB1) device open count is 2 (open)
<debug> [1576269306.467452] Flashing data port (ttyUSB1)...
<debug> [1576269306.467511] (ttyUSB1): port attributes not fully set

After the flash operation, we're done, we've tried as much as possible
to get the TTY port in command mode again, and we report the bearer as
disconnected:

<debug> [1576269307.468803] (ttyUSB1) device open count is 1 (close)
<debug> [1576269307.468867] (ttyUSB1): running init sequence...
<debug> [1576269307.468983] PDP disconnection already sent
<debug> [1576269307.469019] Disconnected bearer
'/org/freedesktop/ModemManager1/Bearer/0'
<info>  [1576269307.469134] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting
-> registered)

And reconnection starts right away....

<info>  [1576269307.469314] Simple connect state (5/8): Register
<debug> [1576269307.469419] Already registered in network '26202',
automatic registration not launched...
<info>  [1576269307.470772] Simple connect state (6/8): Bearer
<debug> [1576269307.470812] Using already existing bearer at
'/org/freedesktop/ModemManager1/Bearer/0'...
<info>  [1576269307.470837] Simple connect state (7/8): Connect
<debug> [1576269307.470884] Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
<info>  [1576269307.470944] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
<debug> [1576269307.471704] Launching 3GPP connection attempt with APN
'web.vodafone.de'
<debug> [1576269307.471858] Looking for best CID...
<debug> [1576269307.471907] (ttyUSB1) device open count is 2 (open)
<debug> [1576269307.472520] (ttyUSB1): --> 'ATE0<CR>'

But the AT commands start to timeout all of them in ttyUSB1. Looks
like it didn't go back to command mode properly.

<debug> [1576269310.839802] (ttyUSB1): --> 'ATV1<CR>'
<debug> [1576269313.221878] loading signal quality...
<debug> [1576269313.221986] loading signal quality...
<debug> [1576269313.222060] (ttyUSB1) device open count is 3 (open)
<warn>  [1576269314.202592] (tty/ttyUSB1) at port timed out 2 consecutive times
<debug> [1576269314.202763] (ttyUSB1): --> 'AT+CMEE=1<CR>'
<warn>  [1576269317.557587] (tty/ttyUSB1) at port timed out 3 consecutive times
<debug> [1576269317.557754] (ttyUSB1): --> 'ATX4<CR>'
<warn>  [1576269320.899703] (tty/ttyUSB1) at port timed out 4 consecutive times
<debug> [1576269320.899875] (ttyUSB1): --> 'AT&C1<CR>'
<warn>  [1576269324.234949] (tty/ttyUSB1) at port timed out 5 consecutive times
<debug> [1576269324.235122] (ttyUSB1): --> 'AT+CGDCONT?<CR>'

So, the patch I wrote seems to be working properly (there are no
further AT commands attempted during a disconnection phase), but that
didn't solve the actual problem. The ttyUSB1 port didn't get
reconfigured in command mode after the PPP session.

No idea what else to do to solve this I'm afraid... :/ Maybe we could
extend the logic and add some automatic recovery mechanism to reset
the modem using the secondary port if we end up seeing that the
primary port is stuck like that? That wouldn't be ideal, but I assume
it's better to have one modem reset than having MM flag the modem as
failed.

-- 
Aleksander
https://aleksander.es