Bug 23820

Created attachment 29355 [details]
dbus-monitor --system

Some users are seeing simultaneous crashes in gnome-power-manager and gnome-session when disconnecting some USB devices. Both crashes have a similar stacktrace.

The crash can be triggered by doing the following steps with the device:

1) Insert, 2) Remove, 3) Insert, 4) Remove - crash

#0  IA__g_str_hash (v=0x0) at /build/buildd/glib2.0-2.21.6/glib/gstring.c:99
	p = (const signed char *) 0x0
	h = <value optimized out>
#1  0xb772bf97 in g_hash_table_remove_internal (hash_table=0x81d1920, 
    key=0x0, notify=1) at /build/buildd/glib2.0-2.21.6/glib/ghash.c:195
	node = <value optimized out>
	node_index = <value optimized out>
	__PRETTY_FUNCTION__ = "g_hash_table_remove_internal"
#2  0xb781696c in IA__g_cclosure_marshal_VOID__STRING (closure=0x81a4250, 
    return_value=0x0, n_param_values=2, param_values=0x8225ad8, 
    invocation_hint=0xbfd13030, marshal_data=0x8070130)
    at /build/buildd/glib2.0-2.21.6/gobject/gmarshal.c:496
	data1 = (gpointer) 0x81e1388
	data2 = (gpointer) 0x81c4880
	__PRETTY_FUNCTION__ = "IA__g_cclosure_marshal_VOID__STRING"
#3  0xb78afc54 in marshal_dbus_message_to_g_marshaller (closure=0x81a4250, 
    return_value=0x0, n_param_values=3, param_values=0x81c4a80, 
    invocation_hint=0xbfd13030, marshal_data=0x0) at dbus-gproxy.c:1680
	value_array = <value optimized out>
	c_marshaller = (
    GSignalCMarshaller) 0x805007c <g_cclosure_marshal_VOID__STRING@plt>
	proxy = (DBusGProxy *) 0x81e1388
	__PRETTY_FUNCTION__ = "marshal_dbus_message_to_g_marshaller"
#4  0xb78080f2 in IA__g_closure_invoke (closure=0x81a4250, return_value=0x0, 
    n_param_values=3, param_values=0x81c4a80, invocation_hint=0xbfd13030)
    at /build/buildd/glib2.0-2.21.6/gobject/gclosure.c:767
	marshal = (
    GClosureMarshal) 0xb78afa80 <marshal_dbus_message_to_g_marshaller>
	marshal_data = (gpointer) 0x0
	__PRETTY_FUNCTION__ = "IA__g_closure_invoke"
#5  0xb781eaf8 in signal_emit_unlocked_R (node=<value optimized out>, 
    detail=<value optimized out>, instance=0x81e1388, emission_return=0x0, 
    instance_and_params=0x81c4a80)
    at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:3247
	tmp = (Handler *) 0xb784c200
	handler = (Handler *) 0x81a0ca0
	accumulator = (SignalAccumulator *) 0x0
	emission = {next = 0x0, instance = 0x81e1388, ihint = {
    signal_id = 142, detail = 727, run_type = G_SIGNAL_RUN_FIRST}, 
  state = EMISSION_RUN, chain_type = 4}
	class_closure = (GClosure *) 0x0
	handler_list = (Handler *) 0xb784c200
	return_accu = <value optimized out>
	accu = {g_type = 0, data = {{v_int = 0, v_uint = 0, v_long = 0, 
      v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, 
      v_pointer = 0x0}, {v_int = 0, v_uint = 0, v_long = 0, v_ulong = 0, 
      v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, v_pointer = 0x0}}}
	signal_id = 142
	max_sequential_handler_number = 140
	return_value_altered = 0
#6  0xb781fedd in IA__g_signal_emit_valist (instance=0x81e1388, 
    signal_id=142, detail=727, var_args=0xbfd131f4 "ôß\211·82Ñ¿\202O\210·")
    at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:2980
	signal_return_type = 4
	node = (SignalNode *) 0x81e7aa8
	i = <value optimized out>
	n_params = 2
	__PRETTY_FUNCTION__ = "IA__g_signal_emit_valist"
#7  0xb7820396 in IA__g_signal_emit (instance=0x81e1388, signal_id=142, 
    detail=727) at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:3037
No locals.
#8  0xb78b0e85 in dbus_g_proxy_manager_filter (connection=0x81eb148, 
    message=0x821d678, user_data=0x81f5910) at dbus-gproxy.c:1733
	proxy = (DBusGProxy *) 0x81e1388
	tri = <value optimized out>
	full_list = (GSList *) 0x82022c8
	tmp = (GSList *) 0x82022c8
	sender = 0x81e1388 "\030c\036\b\004"
	__PRETTY_FUNCTION__ = "dbus_g_proxy_manager_filter"
#9  0xb786ccad in dbus_connection_dispatch (connection=0x81eb148)
    at dbus-connection.c:4446
	filter = (DBusMessageFilter *) 0x0
	next = (DBusList *) 0x81e9ce0
	message = (DBusMessage *) 0x821d678
	link = <value optimized out>
	filter_list_copy = (DBusList *) 0x81e8db8
	message_link = <value optimized out>
	result = <value optimized out>
	status = <value optimized out>
	__FUNCTION__ = "dbus_connection_dispatch"
#10 0xb78a771d in message_queue_dispatch (source=0x81f54e0, callback=0, 
    user_data=0x0) at dbus-gmain.c:101
	connection = (DBusConnection *) 0x81eb148
#11 0xb7739e58 in IA__g_main_context_dispatch (context=0x81c8fb0)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:1960
No locals.
#12 0xb773d700 in g_main_context_iterate (context=0x81c8fb0, 
    block=<value optimized out>, dispatch=1, self=0x81afd88)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2591
	max_priority = 0
	timeout = 0
	some_ready = 1
	nfds = <value optimized out>
	allocated_nfds = <value optimized out>
	fds = <value optimized out>
	__PRETTY_FUNCTION__ = "g_main_context_iterate"
#13 0xb773db6f in IA__g_main_loop_run (loop=0x81fba90)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2799
	self = (GThread *) 0x81afd88
	__PRETTY_FUNCTION__ = "IA__g_main_loop_run"
#14 0xb7b8c5e9 in IA__gtk_main ()
    at /build/buildd/gtk+2.0-2.17.10/gtk/gtkmain.c:1205
	tmp_list = (GList *) 0x81ac990
	functions = (GList *) 0x0
	init = (GtkInitFunction *) 0x81a0b40
	loop = (GMainLoop *) 0x81fba90
#15 0x0806223b in main (argc=1, argv=0xbfd13694) at main.c:524
	sa = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, 
  sa_mask = {__val = {0 <repeats 32 times>}}, sa_flags = 0, 
  sa_restorer = 0x80735e9 <__libc_csu_init+25>}
	error = (GError *) 0x0
	display_str = <value optimized out>
	manager = <value optimized out>
	client_store = (GsmStore *) 0x81ac990
	xsmp_server = (GsmXsmpServer *) 0x81a0b40
	signal_handler = (GdmSignalHandler *) 0x81e3b40
	override_autostart_dirs = (char **) 0x0
	default_session_key = 0x0
	entries = {{long_name = 0x8077aa7 "autostart", short_name = 97 'a', 
    flags = 0, arg = G_OPTION_ARG_STRING_ARRAY, arg_data = 0x8083ad4, 
    description = 0x8077d80 "Override standard autostart directories", 
    arg_description = 0x0}, {long_name = 0x8077ab1 "default-session-key", 
    short_name = 0 '\0', flags = 0, arg = G_OPTION_ARG_STRING, 
    arg_data = 0x8083ad0, 
    description = 0x8077da8 "GConf key used to lookup default session", 
    arg_description = 0x0}, {long_name = 0x8077ac5 "debug", 
    short_name = 0 '\0', flags = 0, arg = G_OPTION_ARG_NONE, 
    arg_data = 0x8083ac8, description = 0x8077acb "Enable debugging code", 
    arg_description = 0x0}, {long_name = 0x8077ae1 "failsafe", 
    short_name = 102 'f', flags = 0, arg = G_OPTION_ARG_NONE, 
    arg_data = 0x8083acc, 
    description = 0x8077dd4 "Do not load user-specified applications", 
    arg_description = 0x0}, {long_name = 0x807b5df "version", 
    short_name = 0 '\0', flags = 0, arg = G_OPTION_ARG_NONE, 
    arg_data = 0x8083ac4, 
    description = 0x8077aea "Version of this application", 
    arg_description = 0x0}, {long_name = 0x0, short_name = 0 '\0', flags = 0, 
    arg = G_OPTION_ARG_NONE, arg_data = 0x0, description = 0x0, 
    arg_description = 0x0}}

The crash is proceeded by the following messages in ~/.xsession-errors:

(gnome-power-manager:17805): devkit-power-gobject-CRITICAL **: dkp_device_get_object_path: assertion `DKP_IS_DEVICE (device)' failed
gnome-session[17622]: devkit-power-gobject-CRITICAL: dkp_device_get_object_path: assertion `DKP_IS_DEVICE (device)' failed

I asked the reporter to run gnome-session with G_DEBUG=fatal_criticals, and he got this backtrace:

Program received signal SIGTRAP, Trace/breakpoint trap.
IA__g_logv (log_domain=<value optimised out>, log_level=G_LOG_LEVEL_CRITICAL, 
    format=0xb77e7ca1 "%s: assertion `%s' failed", 
    args1=0xbf85fc2c "U\301\a\b{\273\a\b\320\17\366\267\210\361\234\b\240\1{\267") at /build/buildd/glib2.0-2.21.6/glib/gmessages.c:512
512	/build/buildd/glib2.0-2.21.6/glib/gmessages.c: No such file or directory.
	in /build/buildd/glib2.0-2.21.6/glib/gmessages.c
#0  IA__g_logv (log_domain=<value optimised out>, 
    log_level=G_LOG_LEVEL_CRITICAL, 
    format=0xb77e7ca1 "%s: assertion `%s' failed", 
    args1=0xbf85fc2c "U\301\a\b{\273\a\b\320\17\366\267\210\361\234\b\240\1{\267") at /build/buildd/glib2.0-2.21.6/glib/gmessages.c:512
#1  0xb77aff96 in IA__g_log (log_domain=0x807b5c3 "devkit-power-gobject", 
    log_level=G_LOG_LEVEL_CRITICAL, 
    format=0xb77e7ca1 "%s: assertion `%s' failed")
    at /build/buildd/glib2.0-2.21.6/glib/gmessages.c:526
#2  0xb77b01fb in IA__g_return_if_fail_warning (
    log_domain=0x807b5c3 "devkit-power-gobject", 
    pretty_function=0x807c155 "dkp_device_get_object_path", 
    expression=0x807bb7b "DKP_IS_DEVICE (device)")
    at /build/buildd/glib2.0-2.21.6/glib/gmessages.c:541
#3  0x08071a89 in dkp_device_get_object_path ()
#4  0x0807017b in dkp_device_removed_cb ()
#5  0xb788296c in IA__g_cclosure_marshal_VOID__STRING (closure=0x89c79e8, 
    return_value=0x0, n_param_values=2, param_values=0x89f7040, 
    invocation_hint=0xbf85fe40, marshal_data=0x8070130)
    at /build/buildd/glib2.0-2.21.6/gobject/gmarshal.c:496
#6  0xb791bc54 in marshal_dbus_message_to_g_marshaller (closure=0x89c79e8, 
    return_value=0x0, n_param_values=3, param_values=0x89a3548, 
    invocation_hint=0xbf85fe40, marshal_data=0x0) at dbus-gproxy.c:1680
#7  0xb78740f2 in IA__g_closure_invoke (closure=0x89c79e8, return_value=0x0, 
    n_param_values=3, param_values=0x89a3548, invocation_hint=0xbf85fe40)
    at /build/buildd/glib2.0-2.21.6/gobject/gclosure.c:767
#8  0xb788aaf8 in signal_emit_unlocked_R (node=<value optimised out>, 
    detail=<value optimised out>, instance=0x89bdc78, emission_return=0x0, 
    instance_and_params=0x89a3548)
    at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:3247
#9  0xb788bedd in IA__g_signal_emit_valist (instance=0x89bdc78, signal_id=142, 
    detail=714, var_args=0xbf860004 "\364\237\220\267H")
    at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:2980
#10 0xb788c396 in IA__g_signal_emit (instance=0x89bdc78, signal_id=142, 
    detail=714) at /build/buildd/glib2.0-2.21.6/gobject/gsignal.c:3037
#11 0xb791ce85 in dbus_g_proxy_emit_remote_signal (connection=0x89cde40, 
    message=0x89c6c00, user_data=0x89c7d30) at dbus-gproxy.c:1733
#12 dbus_g_proxy_manager_filter (connection=0x89cde40, message=0x89c6c00, 
    user_data=0x89c7d30) at dbus-gproxy.c:1300
#13 0xb78d8cad in dbus_connection_dispatch () from /lib/libdbus-1.so.3
#14 0xb791371d in message_queue_dispatch (source=0x89c7900, callback=0, 
    user_data=0x0) at dbus-gmain.c:101
#15 0xb77a5e58 in g_main_dispatch (context=0x89a4fb0)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:1960
#16 IA__g_main_context_dispatch (context=0x89a4fb0)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2513
#17 0xb77a9700 in g_main_context_iterate (context=0x89a4fb0, 
    block=<value optimised out>, dispatch=1, self=0x898bd88)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2591
#18 0xb77a9b6f in IA__g_main_loop_run (loop=0x89e15c0)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2799
#19 0xb7bf85e9 in IA__gtk_main ()
    at /build/buildd/gtk+2.0-2.17.10/gtk/gtkmain.c:1205
#20 0x0806223b in main (argc=1, argv=0xbf8604a4) at main.c:524

What seems to be happening is that dkp_client_get_device returns NULL for the device just removed because it doesn't exist in the hash table. This probably shouldn't make the client crash anyway.

I asked the reporter to monitor the system bus when inserting and removing his device. The interesting bits are summarized below, and show that there is a DeviceAdded the first time the device is connected, then a DeviceRemoved when it is disconnected, but there is no DeviceAdded signal when the device is reconnected. When the device is removed for the second time, the DeviceRemoved triggers the crash because the device does not exist in the hash table in the client.

signal sender=:1.813 -> dest=(null destination) serial=52 path=/org/freedesktop/DeviceKit/Power; interface=org.freedesktop.DeviceKit.Power; member=DeviceAdded
   string "/org/freedesktop/DeviceKit/Power/devices/keyboard_5_2"
----
signal sender=:1.813 -> dest=(null destination) serial=59 path=/org/freedesktop/DeviceKit/Power; interface=org.freedesktop.DeviceKit.Power; member=DeviceRemoved
   string "/org/freedesktop/DeviceKit/Power/devices/keyboard_5_2"
----
signal sender=:1.813 -> dest=(null destination) serial=60 path=/org/freedesktop/DeviceKit/Power; interface=org.freedesktop.DeviceKit.Power; member=DeviceRemoved
   string "/org/freedesktop/DeviceKit/Power/devices/keyboard_5_2"

I also asked the reporter to run the daemon with --verbose to capture the output when he does this (attached). This shows that when the device is connected for the second time, it is treated as a change event because it still appears in the device list. This is why there is no second DeviceAdded signal:

TI:19:32:22	TH:0xa04cb78	FI:dkp-daemon.c	FN:dkp_daemon_uevent_signal_handler_cb,879
 - remove /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1
*** WARNING ***
TI:19:32:22	TH:0xa04cb78	FI:dkp-device.c	FN:dkp_device_removed,383
 - do something here?
TI:19:32:26	TH:0xa04cb78	FI:dkp-daemon.c	FN:dkp_daemon_uevent_signal_handler_cb,876
 - add /sys/devices/pci0000:00/0000:00:1a.1/usb4/4-1
TI:19:32:26	TH:0xa04cb78	FI:dkp-daemon.c	FN:dkp_daemon_device_add,819
 - treating add event as change event on /org/freedesktop/DeviceKit/Power/devices/keyboard_4_1
TI:19:32:26	TH:0xa04cb78	FI:dkp-daemon.c	FN:dkp_daemon_device_changed,674
 - changed /org/freedesktop/DeviceKit/Power/devices/keyboard_4_1

I haven't debugged this any further yet, but I suspect that the DkpDevice is not finalized when the device is removed the first time.