[regression] ModemManager disconnects after ~30 sec
Description
using Ubuntu Bionic 18.04 ModemManager version 1.6.8 is fine.
there is an update to ModemManager 1.10.0 ~ 30 sec after my device connects the connection fails.
Cause
i downloaded the ModemManager source and used git bisect to find the cause. it is in ModemManager 1.8 commit# e040ee27
Logs
attached are full logs of ModemManager --debug from the 2 git bisect commits
mm-good-610a6299e1b68dd161e9a8f33aca577756191477.log
mm-bad-e040ee27a0b418926cc99a6846c86ff6397ee560.log
relevant part
Good log commit# 610a6299
<debug> [1556691449.551707] Periodic signal quality checks scheduled in 30s
<debug> [1556691449.551788] (rfcomm0): --> 'ATDT#777<CR>'
<debug> [1556691451.963530] (rfcomm0): <-- '<CR><LF>CONNECT 2400000<CR><LF>'
<debug> [1556691451.963659] [rfcomm0] Setting flow control: rts-cts
<debug> [1556691451.963684] (rfcomm0): enabling RTS/CTS flow control
<debug> [1556691451.963758] (rfcomm0): port now connected
<debug> [1556691451.963843] (rfcomm0) device open count is 2 (close)
<debug> [1556691451.963925] Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
<info> [1556691451.964179] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
<info> [1556691451.964503] Simple connect state (8/8): All done
<debug> [1556691452.010127] (net/ppp0): adding device at sysfs path: /sys/devices/virtual/net/ppp0
<debug> [1556691452.010205] (net/ppp0): could not get port's parent device
<debug> [1556691452.010216] (net/ppp0): port not candidate
<debug> [1556691479.769507] Running registration checks (CDMA1x: 'yes', EV-DO: 'yes')
<debug> [1556691479.769575] Will skip all QCDM-based registration checks
<debug> [1556691479.769594] Will skip generic detailed registration check, we don't have Sprint commands
<debug> [1556691479.769631] loading signal quality...
<debug> [1556691479.769686] Starting QCDM-based registration checks
<debug> [1556691479.769722] Skipping all QCDM-based checks and falling back to AT-based checks
<debug> [1556691479.769735] Starting AT-based registration checks
<debug> [1556691479.769769] Couldn't refresh signal quality: 'No AT port available to run command'
<debug> [1556691479.769801] EVDO registration: 0
<debug> [1556691479.769815] CDMA1x registration: 1
<debug> [1556691479.769826] Fallback access tech: 0x00000400
<debug> [1556691479.769839] Fallback access technology: 0x00000400
<warn> [1556691479.769885] Could not get service status: No AT port available to run command
<debug> [1556691479.769915] Couldn't refresh CDMA registration status: 'No AT port available to run command'
<debug> [1556691479.769955] Periodic signal quality checks scheduled in 30s
<warn> [1556691481.769459] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691486.770972] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691491.770995] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691496.772267] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691501.772560] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691506.772860] checking if connected failed: Couldn't load connection status: cid not defined
<debug> [1556691509.770067] Running registration checks (CDMA1x: 'yes', EV-DO: 'yes')
<debug> [1556691509.770148] Will skip all QCDM-based registration checks
<debug> [1556691509.770169] Will skip generic detailed registration check, we don't have Sprint commands
<debug> [1556691509.770228] Signal quality value not updated in 60s, marking as not being recent
<debug> [1556691509.770329] loading signal quality...
<debug> [1556691509.770393] Starting QCDM-based registration checks
<debug> [1556691509.770415] Skipping all QCDM-based checks and falling back to AT-based checks
<debug> [1556691509.770428] Starting AT-based registration checks
<debug> [1556691509.770622] Couldn't refresh signal quality: 'No AT port available to run command'
<debug> [1556691509.770653] EVDO registration: 0
<debug> [1556691509.770667] CDMA1x registration: 1
<debug> [1556691509.770679] Fallback access tech: 0x00000400
<debug> [1556691509.770691] Fallback access technology: 0x00000400
<warn> [1556691509.770736] Could not get service status: No AT port available to run command
<debug> [1556691509.770787] Couldn't refresh CDMA registration status: 'No AT port available to run command'
<debug> [1556691509.770827] Periodic signal quality checks scheduled in 30sBad log commit# e040ee27
<debug> [1556691159.601126] Periodic signal quality checks scheduled in 30s
<debug> [1556691159.601176] (rfcomm0): --> 'ATDT#777<CR>'
<debug> [1556691162.411482] (rfcomm0): <-- '<CR><LF>CONNECT 2400000<CR><LF>'
<debug> [1556691162.411579] [rfcomm0] Setting flow control: rts-cts
<debug> [1556691162.411612] (rfcomm0): enabling RTS/CTS flow control
<debug> [1556691162.411646] (rfcomm0): port now connected
<debug> [1556691162.411690] (rfcomm0) device open count is 2 (close)
<debug> [1556691162.411719] Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
<info> [1556691162.411860] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
<info> [1556691162.411990] Simple connect state (8/8): All done
<debug> [1556691162.443156] (net/ppp0): adding device at sysfs path: /sys/devices/virtual/net/ppp0
<debug> [1556691162.443250] (net/ppp0): could not get port's parent device
<debug> [1556691162.443266] (net/ppp0): port not candidate
<debug> [1556691189.790802] Running registration checks (CDMA1x: 'yes', EV-DO: 'yes')
<debug> [1556691189.790831] Will skip all QCDM-based registration checks
<debug> [1556691189.790836] Will skip generic detailed registration check, we don't have Sprint commands
<debug> [1556691189.790848] loading signal quality...
<debug> [1556691189.790866] Starting QCDM-based registration checks
<debug> [1556691189.790877] Skipping all QCDM-based checks and falling back to AT-based checks
<debug> [1556691189.790881] Starting AT-based registration checks
<debug> [1556691189.790894] Couldn't refresh signal quality: 'No AT port available to run command'
<debug> [1556691189.790907] EVDO registration: 0
<debug> [1556691189.790912] CDMA1x registration: 1
<debug> [1556691189.790915] Fallback access tech: 0x00000400
<debug> [1556691189.790919] Fallback access technology: 0x00000400
<debug> [1556691189.790935] No CDMA service found
<debug> [1556691189.790939] All CDMA registration state checks done
<debug> [1556691189.790970] Connected bearer not registered in CDMA network
<debug> [1556691189.791007] Periodic signal quality checks scheduled in 30s
<warn> [1556691192.770226] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691197.770993] checking if connected failed: Couldn't load connection status: cid not defined
<warn> [1556691202.770912] checking if connected failed: Couldn't load connection status: cid not defined
<debug> [1556691204.769118] Forcing bearer disconnection, not registered in CDMA network
<debug> [1556691204.769168] Forcing disconnection of bearer '/org/freedesktop/ModemManager1/Bearer/0'
<info> [1556691204.769219] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
<debug> [1556691204.769684] Reopening data port (rfcomm0)...
<debug> [1556691204.769721] (rfcomm0) reopening port (2)
<debug> [1556691204.769736] (rfcomm0) device open count is 1 (close)
<debug> [1556691204.769749] (rfcomm0) device open count is 0 (close)
<debug> [1556691204.769767] (rfcomm0) closing serial port...
<debug> [1556691204.769790] (rfcomm0): port now disconnected
<debug> [1556691204.769855] (rfcomm0) serial port closed
<debug> [1556691204.781444] (tty/rfcomm0): adding device at sysfs path: /sys/devices/virtual/tty/rfcomm0
<info> [1556691204.781472] (tty/rfcomm0): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:256/rfcomm0'
<debug> [1556691204.781483] Removing empty device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:256/rfcomm0'
<debug> [1556691204.781595] Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
<debug> [1556691204.781610] [device /sys/devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:256/rfcomm0] unexported modem from path '/org/freedesktop/ModemManager1/Modem/0'
<debug> [1556691204.781620] Periodic signal checks disabledthanks