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