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:
[1576269305.4461] kill child process 'pppd' (5769): wait for
process to terminate after sending SIGTERM (15) (send SIGKILL in 1500
milliseconds)...
[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.
[1576269305.448567] Disconnecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
[1576269305.448632] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
disconnecting)
[1576269305.449065] Sending PDP context deactivation in
secondary port...
[1576269305.449093] (ttyUSB3) device open count is 2 (open)
[1576269305.449167] (ttyUSB3): --> 'AT+CGACT=0,1'
[1576269305.464964] (ttyUSB3): <-- 'OK'
We fully close the ttyUSB1 at this point, and we wait 1 full second
with the port closed completely:
[1576269305.465193] Reopening data port (ttyUSB1)...
[1576269305.465219] (ttyUSB1) reopening port (2)
[1576269305.465230] (ttyUSB1) device open count is 1 (close)
[1576269305.465241] (ttyUSB1) device open count is 0 (close)
[1576269305.465257] (ttyUSB1) closing serial port...
[1576269305.465272] (ttyUSB1): port now disconnected
[1576269305.465317] (ttyUSB1) serial port closed
[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.
[1576269305.535348] Simple connect started...
[1576269305.535385]PIN: unspecified
[1576269305.535395]Operator ID: unspecified
[1576269305.535405]Allowed roaming: yes
[1576269305.535415]APN: web.vodafone.de
[1576269305.535426]IP family: ipv4
[1576269305.535451]Allowed authentication: none, pap,
chap, mschap, mschapv2, eap
[1576269305.535463]User: unspecified
[1576269305.535473]Password: unspecified
[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)
[1576269306.466655] (ttyUSB1) opening serial port...
[1576269306.467097] (ttyUSB1): setting up baudrate: 57600
[1576269306.467174] (ttyUSB1): no flow control explicitly
requested for device
[1576269306.467223] (ttyUSB1): port attributes not fully set
[1576269306.467355] (ttyUSB1) device open count is 1 (open)
[1576269306.467383] (ttyUSB1) device open count is 2 (open)
[1576269306.467452] Flashing data port (ttyUSB1)...
[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:
[1576269307.468803] (ttyUSB1) device open count is 1 (close)
[1576269307.468867] (ttyUSB1): running init sequence...
[1576269307.468983] PDP disconnection already sent
[1576269307.469019] Disconnected bearer
'/org/freedesktop/ModemManager1/Bearer/0'
[1576269307.469134] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting
-> registered)
And reconnection starts right away
[1576269307.469314] Simple connect state (5/8): Register
[1576269307.469419] Already registered in network '26202',
automatic registration not launched...
[1576269307.470772] Simple connect state (6/8): Bearer
[1576269307.470812] Using already existing bearer at
'/org/freedesktop/ModemManager1/Bearer/0'...
[1576269307.470837] Simple connect state (7/8): Connect
[1576269307.470884] Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
[1576269307.470944] Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
[1576269307.471704] Launching 3GPP connection attempt with APN
'web.vodafone.de'
[1576269307.471858] Looking for best CID...
[1576269307.471907] (ttyUSB1) device open count
