[PATCH] serial-port: turn open_count assertion in mm_serial_port_close into simple return

[Ben Chan]

On Sat, Jan 11, 2014 at 2:32 PM, Aleksander Morgado
<aleksander at aleksander.es> wrote:
>
> On 11/01/14 01:54, Ben Chan wrote:
> > When mm_serial_port_close is clearing a non-empty command queue, the
> > response handler callback of a command could potentially call
> > mm_serial_port_close again (e.g. via at_command_context_free,
> > at_sequence_context_free in mm-base-modem-at.c), which triggers the
> > following assertion:
> >
> >   ModemManager: <debug> (ttyACM0) forced to close port
> >   ModemManager: <debug> (ttyACM0) device open count is 0 (close)
> >   ModemManager: <debug> (ttyACM0) closing serial port...
> >   ModemManager: <debug> (ttyACM0) serial port closed
> >   ModemManager: mm_serial_port_close: assertion `priv->open_count > 0' failed
> >
> > The assertion is confusing as the condition is normal. This patch thus turns
> > the 'priv->open_count > 0' assertion in mm_serial_port_close into a simple
> > return.
> > ---
>
> I wouldn't say the condition is normal. Each port open request has its
> corresponding port close request. The only case in which we should not
> warn about close requests happening to a port with open_count==0 is when
> the port was forced-closed, which is already handled for what I can see
> "if (priv->forced_close) return;".
>
> Now, I'm not sure in which situation you got that warning, but the
> warning is indeed useful to detect issues with port open/close count
> balance... The logs say that the ttyACM0 was forced-close; maybe
> priv->forced_close wasn't set?
>

The following call sequence illustrate the problem.

1. mm_serial_port_close_force calls mm_serial_port_close.
2. Before mm_serial_port_close_force even finishes and returns, it
invokes a response callback of a command in priv->queue
3. The response callback completes and frees the associated context,
which calls mm_serial_port_close_force again
4. The assertion is caused by the second call to mm_serial_port_close_force.

mm_serial_port_close_force {
    ...
    priv->open_count = 1;
    mm_serial_port_close (self) {
        if (priv->forced_close)    // forced_close = FALSE
            return;
        g_return_if_fail (priv->open_count > 0);   //  open_count = 1

        priv->open_count--;    // open_count = 0

        ...

        for (i = 0; i < g_queue_get_length (priv->queue); i++) {
            MMQueueData *item = g_queue_peek_nth (priv->queue, i);

            if (item->callback) {
                ....
                g_warn_if_fail (MM_SERIAL_PORT_GET_CLASS
(self)->handle_response != NULL);
                error = g_error_new_literal (MM_SERIAL_ERROR,
                                             MM_SERIAL_ERROR_SEND_FAILED,
                                             "Serial port is now closed");
                ...
                MM_SERIAL_PORT_GET_CLASS (self)->handle_response (self,
                                                                 response,
                                                                 error,
                                                                 item->callback,

item->user_data) {

                      // !!! here handle_response will eventually
triggers the following sequence:

                       at_command_parse_response {
                           at_command_context_free {

                               mm_serial_port_close (self) {
                                   if (priv->forced_close)    //
forced_close = FALSE
                                      return;
                                   g_return_if_fail (priv->open_count
> 0);   //  open_count = 0   --> assertion!
                                }
                          }
                       }

                }

                g_error_free (error);
                g_byte_array_free (response, TRUE);
            }
            ....
        }

        }
    }
    priv->forced_close = TRUE;
    ...
}