GNOME Bugzilla – Bug 701809
[MM 0.8] bluetooth DUN disconnects fail
Last modified: 2015-03-03 08:51:58 UTC
Created attachment 246275 [details] BT disconnect failure log I moved the phone out of range, which caused Bluez to tell NM the link was disconnected, which caused NM to ask ModemManager to disconnect the bearer. MM has some trouble with this, apparently, because it thinks it's still connected and it only has one port. I wonder if the rfcomm port sends SIGHUP or some other indication when it gets disconnected that MM is ignoring?
Relevant lines are: [mm-bearer.c:756] mm_bearer_disconnect(): Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/2' [mm-iface-modem.c:1203] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/3: state changed (connected -> disconnecting) [mm-broadband-bearer.c:1409] disconnect_cdma(): Reopening data port (rfcomm0)... [mm-serial-port.c:1296] mm_serial_port_reopen(): (rfcomm0) reopening port (2) [mm-serial-port.c:1003] mm_serial_port_close(): (rfcomm0) device open count is 1 (close) [mm-serial-port.c:1003] mm_serial_port_close(): (rfcomm0) device open count is 0 (close) [mm-serial-port.c:1019] mm_serial_port_close(): (rfcomm0) closing serial port... [mm-port.c:149] mm_port_set_connected(): (rfcomm0): port now disconnected [mm-serial-port.c:1050] mm_serial_port_close(): (rfcomm0) serial port closed [mm-serial-port.c:891] mm_serial_port_open(): (rfcomm0) opening serial port... [mm-bearer.c:684] disconnect_ready(): Couldn't disconnect bearer '/org/freedesktop/ModemManager1/Bearer/2' [mm-iface-modem.c:1203] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/3: state changed (disconnecting -> connected)
Created attachment 246357 [details] [review] Make port reopening failures non-fatal For what I can see we get no indication that the rfcomm port is either disconnected or lost. The error here seems to be from port reopening; once we fully close the port we cannot re-open it again, and the disconnection procedure fails. It's hard to say what to do here; should we just ignore the errors during disconnection? or maybe even mark the modem as fully invalid? (e.g. via mm_base_modem_set_valid (self, FALSE);) The patch attached makes the reopen errors non-fatal, but I don't think it's enough. Could you maybe retry with the patch in?
What's odd is that when NetworkManager disconnects bluetooth, the rfcomm port should actually just go away, and MM would get a udev removed signal. Not sure why that's not happening. I'll investigate further (though with kernel 3.9.4, bluetooth panics a lot on disconnect)
Yeah, bluetooth rfcomm disconnect is busted since 3.8-rc1, see https://lkml.org/lkml/2013/5/16/55.
We're better now as of 41b7e7b04 but not quite all there: ModemManager[1894]: <debug> [1413218725.821402] [mm-broadband-bearer.c:1440] disconnect_cdma(): Reopening data port (rfcomm0)... ModemManager[1894]: <debug> [1413218725.821425] [mm-port-serial.c:1558] mm_port_serial_reopen(): (rfcomm0) reopening port (2) ModemManager[1894]: <debug> [1413218725.821456] [mm-port-serial.c:1294] _close_internal(): (rfcomm0) device open count is 1 (close) ModemManager[1894]: <debug> [1413218725.821473] [mm-port-serial.c:1294] _close_internal(): (rfcomm0) device open count is 0 (close) ModemManager[1894]: <debug> [1413218725.821490] [mm-port-serial.c:1310] _close_internal(): (rfcomm0) closing serial port... ModemManager[1894]: <debug> [1413218725.821509] [mm-port.c:95] mm_port_set_connected(): (rfcomm0): port now disconnected ModemManager[1894]: <debug> [1413218725.821579] [mm-port-serial.c:1359] _close_internal(): (rfcomm0) serial port closed ModemManager[1894]: <info> [1413218725.885373] [mm-base-manager.c:375] device_removed(): (tty/rfcomm0): released by modem /sys/devices/virtual/tty/rfcomm0 ModemManager[1894]: <debug> [1413218725.885420] [mm-base-manager.c:380] device_removed(): Removing empty device '/sys/devices/virtual/tty/rfcomm0' ModemManager[1894]: <debug> [1413218725.885639] [mm-base-bearer.c:895] base_bearer_dbus_unexport(): Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/1' ModemManager[1894]: <debug> [1413218725.885677] [mm-device.c:382] unexport_modem(): Unexported modem '/sys/devices/virtual/tty/rfcomm0' from path '/org/freedesktop/ModemManager1/Modem/3' ModemManager[1894]: <debug> [1413218726.823307] [mm-port-serial.c:1099] mm_port_serial_open(): (rfcomm0) opening serial port... ModemManager[1894]: <warn> [1413218726.823927] [mm-port-serial.c:1123] mm_port_serial_open(): (rfcomm0) could not open serial device (2) ModemManager[1894]: <debug> [1413218726.824152] [mm-base-bearer.c:688] disconnect_ready(): Couldn't disconnect bearer '/org/freedesktop/ModemManager1/Bearer/1' ModemManager[1894]: _close_internal: assertion 'self->priv->open_count > 0' failed ModemManager[1894]: <debug> [1413218726.824950] [mm-port-serial.c:1421] port_serial_close_force(): (rfcomm0) forced to close port ModemManager[1894]: <debug> [1413218726.825078] [mm-base-modem.c:1493] finalize(): Modem (Generic) '/sys/devices/virtual/tty/rfcomm0' completely disposed
Wait, why not quite all there? The rfcomm device is removed by the kernel, we get notified about it by udev, and we fully remove the Modem device. Isn't that what we're supposed to do?
"not quite all there" because MM tries to re-open the port again for disconnect_ready(), despite the act that the port cannot be opened anymore... Plus then we have the assertion: ModemManager[1894]: _close_internal: assertion 'self->priv->open_count > 0' failed which we shouldn't be hitting.
(In reply to comment #7) > "not quite all there" because MM tries to re-open the port again for > disconnect_ready(), despite the act that the port cannot be opened anymore... > > Plus then we have the assertion: > > ModemManager[1894]: _close_internal: assertion 'self->priv->open_count > 0' > failed > > which we shouldn't be hitting. Could you review and retry the patches at the "aleksander/cancellations" branch in git? I think they cover this specific issue, and I also ended up plugging in the modem-wide cancellation in all QMI and MBIM operations, among other things.
Moved this bug to the new ModemManager bugzilla at freedesktop.org: https://bugs.freedesktop.org/show_bug.cgi?id=89404