core: better debugging of serial port open/close

Some devices don't interact well with the option drivr or the usb-serial
layer; they don't respond to the USB data requests and thus data never
gets written to that port.  When close(2) is called, that data is still
pending and so the tty layer waits 30 seconds before returning from
the close.  This is the 'closing_wait' value, which unfortunately is
not able to be modified by ModemManager because most serial drivers
for 3G devices don't implement the .ioctl handler or its TCIOSSERIAL
option to change closing_wait.

Print out open/close timestamps to help debug this issue and get a
list of modems that have this problem.
This commit is contained in:
Dan Williams
2010-09-27 15:52:29 -05:00
parent 3c8c3f7425
commit 81d0fd148f

View File

@@ -684,6 +684,7 @@ mm_serial_port_open (MMSerialPort *self, GError **error)
MMSerialPortPrivate *priv;
char *devfile;
const char *device;
GTimeVal tv;
g_return_val_if_fail (MM_IS_SERIAL_PORT (self), FALSE);
@@ -696,7 +697,13 @@ mm_serial_port_open (MMSerialPort *self, GError **error)
goto success;
}
g_message ("(%s) opening serial device...", device);
if (mm_options_debug ()) {
g_get_current_time (&tv);
g_debug ("<%ld.%ld> (%s) opening serial port...",
tv.tv_sec, tv.tv_usec, device);
} else
g_message ("(%s) opening serial port...", device);
devfile = g_strdup_printf ("/dev/%s", device);
errno = 0;
priv->fd = open (devfile, O_RDWR | O_EXCL | O_NONBLOCK | O_NOCTTY);
@@ -746,8 +753,6 @@ mm_serial_port_open (MMSerialPort *self, GError **error)
success:
priv->open_count++;
if (mm_options_debug ()) {
GTimeVal tv;
g_get_current_time (&tv);
g_debug ("<%ld.%ld> (%s) device open count is %d (open)",
tv.tv_sec, tv.tv_usec, device, priv->open_count);
@@ -774,6 +779,7 @@ mm_serial_port_close (MMSerialPort *self)
{
MMSerialPortPrivate *priv;
const char *device;
GTimeVal tv;
int i;
g_return_if_fail (MM_IS_SERIAL_PORT (self));
@@ -786,8 +792,6 @@ mm_serial_port_close (MMSerialPort *self)
priv->open_count--;
if (mm_options_debug ()) {
GTimeVal tv;
g_get_current_time (&tv);
g_debug ("<%ld.%ld> (%s) device open count is %d (close)",
tv.tv_sec, tv.tv_usec, device, priv->open_count);
@@ -802,7 +806,14 @@ mm_serial_port_close (MMSerialPort *self)
}
if (priv->fd >= 0) {
g_message ("(%s) closing serial device...", device);
GTimeVal tv_start, tv_end;
g_get_current_time (&tv_start);
if (mm_options_debug ()) {
g_debug ("<%ld.%ld> (%s) closing serial port...",
tv_start.tv_sec, tv_start.tv_usec, device);
} else
g_message ("(%s) closing serial port...", device);
mm_port_set_connected (MM_PORT (self), FALSE);
@@ -817,8 +828,23 @@ mm_serial_port_close (MMSerialPort *self)
mm_serial_port_flash_cancel (self);
tcsetattr (priv->fd, TCSANOW, &priv->old_t);
tcflush (priv->fd, TCIOFLUSH);
close (priv->fd);
priv->fd = -1;
g_get_current_time (&tv_end);
if (mm_options_debug ()) {
g_debug ("<%ld.%ld> (%s) serial port closed",
tv_end.tv_sec, tv_end.tv_usec, device);
}
/* Some ports don't respond to data and when close is called
* the serial layer waits up to 30 second (closing_wait) for
* that data to send before giving up and returning from close().
* Log that. See GNOME bug #630670 for more details.
*/
if (tv_end.tv_sec - tv_start.tv_sec > 20)
g_warning ("(%s): close blocked by driver for more than 20 seconds!", device);
}
/* Clear the command queue */