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 _______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
