Skip to content

port-serial: avoid finalizing the port mid-close

Lubomir Rintel requested to merge NetworkManager/ModemManager:lr/close-crash into master 
  ModemManager[31337]: <debug> [1570093010.207045] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/33'
  ModemManager[31337]: <info>  [1570093010.207075] Modem /org/freedesktop/ModemManager1/Modem/33: state changed (connected -> disconnecting)
  ModemManager[31337]: <debug> [1570093010.207214] Reopening data port (modemu)...
  ModemManager[31337]: <debug> [1570093010.207229] (modemu) reopening port (2)
  ModemManager[31337]: <debug> [1570093010.207247] (modemu) device open count is 1 (close)
  ModemManager[31337]: <debug> [1570093010.207269] (modemu) device open count is 0 (close)
  ModemManager[31337]: <debug> [1570093010.207287] (modemu) closing serial port...
  ModemManager[31337]: <debug> [1570093010.207293] (modemu): port now disconnected
  ModemManager[31337]: <debug> [1570093010.207327] (modemu) serial port closed
  ModemManager[31337]: <debug> [1570093011.208451] (modemu) opening serial port...
  ModemManager[31337]: <debug> [1570093011.208651] (modemu): setting up baudrate: 57600
  ModemManager[31337]: <debug> [1570093011.208665] (modemu): no flow control explicitly requested for device
  ModemManager[31337]: <debug> [1570093011.208713] (modemu) device open count is 1 (open)
  ModemManager[31337]: <debug> [1570093011.208719] (modemu) device open count is 2 (open)
  ModemManager[31337]: <debug> [1570093011.208728] Flashing data port (modemu)...
  ModemManager[31337]: <debug> [1570093011.208753] (modemu): port attributes not fully set
  ModemManager[31337]: <info>  [1570093012.208004] (tty/modemu): released by device '/sys/devices/pci0000:00/0000:00:00.0'
  ModemManager[31337]: <debug> [1570093012.208026] Removing empty device '/sys/devices/pci0000:00/0000:00:00.0'
  ModemManager[31337]: <debug> [1570093012.208135] Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/33'
  ModemManager[31337]: <debug> [1570093012.208159] [device /sys/devices/pci0000:00/0000:00:00.0] unexported modem from path '/org/freedesktop/ModemManager1/Modem/33'
  ModemManager[31337]: <debug> [1570093012.208169] Periodic signal checks disabled
  ModemManager[31337]: <debug> [1570093012.208269] (modemu) unexpected port hangup!
  ModemManager[31337]: <debug> [1570093012.208280] (modemu) forced to close port
  ModemManager[31337]: <debug> [1570093012.208297] (modemu) device open count is 0 (close)
  ModemManager[31337]: <debug> [1570093012.208317] Couldn't disconnect bearer '/org/freedesktop/ModemManager1/Bearer/33'
  ModemManager[31337]: <debug> [1570093012.208398] Modem (Generic) '/sys/devices/pci0000:00/0000:00:00.0' completely disposed
  **
  ERROR:mm-port-serial.c:2100:finalize: assertion failed: (self->priv->iochannel == NULL)

What happened here is that port_serial_close_force() -> _close_internal() -> mm_port_serial_flash_cancel() drops the last port reference.

finalize() is called between the open count drops, but iochannel is not released yet and trips an assertion:

  #0  0x00007f46e3f678df in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
  #1  0x00007f46e3f51cf5 in __GI_abort () at abort.c:79
  #2  0x00007f46e452f003 in g_assertion_message (...) at gtestutils.c:2532
  #3  0x00007f46e4587fde in g_assertion_message_expr (...) at gtestutils.c:2555
  #4  0x000055bdb0212caa in finalize (object=0x55bdb09ab5f0 [MMPortSerialAt]) at mm-port-serial.c:2067
  #5  0x00007f46e48418a9 in g_object_unref (_object=<optimized out>) at gobject.c:3340
  #6  0x00007f46e48418a9 in g_object_unref (_object=0x55bdb09ab5f0) at gobject.c:3232
  #7  0x00007f46e4b124be in g_task_finalize (object=0x55bdb0993d10 [GTask]) at gtask.c:634
  #8  0x00007f46e48418a9 in g_object_unref (_object=<optimized out>) at gobject.c:3340
  #9  0x00007f46e48418a9 in g_object_unref (_object=0x55bdb0993d10) at gobject.c:3232
  #10 0x000055bdb0211ed6 in mm_port_serial_flash_cancel (self=<optimized out>) at mm-port-serial.c:1744
  #11 0x000055bdb0211fec in _close_internal (self=self@entry=0x55bdb09ab5f0 [MMPortSerialAt], force=force@entry=1) at mm-port-serial.c:1394
  #12 0x000055bdb02124e6 in port_serial_close_force (self=0x55bdb09ab5f0 [MMPortSerialAt]) at mm-port-serial.c:1523
  #13 0x000055bdb02124e6 in port_serial_close_force (self=0x55bdb09ab5f0 [MMPortSerialAt]) at mm-port-serial.c:1504
  #14 0x000055bdb0212863 in common_input_available (self=0x55bdb09ab5f0 [MMPortSerialAt], condition=<optimized out>) at mm-port-serial.c:971
  #15 0x00007f46e456067d in g_main_dispatch (context=0x55bdb0944700) at gmain.c:3176
  #16 0x00007f46e456067d in g_main_context_dispatch (context=context@entry=0x55bdb0944700) at gmain.c:3829
  #17 0x00007f46e4560a48 in g_main_context_iterate (context=0x55bdb0944700, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3902
  #18 0x00007f46e4560d72 in g_main_loop_run (loop=0x55bdb0927a20) at gmain.c:4098
  #19 0x000055bdb017e225 in main (argc=<optimized out>, argv=<optimized out>) at main.c:181

Merge request reports