Sugar crashing when saving a journal entry upon closing an activity

[sdz]

In the most recent SoaS snapshot, X gets apparently killed each time one saves a Journal entry. At least, the user is logged out and logged in again. I haven't seen this in 0.85.2, so this might have been introduced with 0.85.3. But I'm just guessing here, it could also be caused by the new display manager in SoaS... basically putting it here as a self-reminder to investigate.

[sascha_silbe]

Happened to me today in sugar-jhbuild on DebXO:

==> shell.log <==
1249389164.020492 DEBUG root: __reply_handler_cb
The program 'sugar-session' received an X Window System error.
This probably reflects a bug in the program.
The error was 'BadWindow (invalid Window parameter)'.
  (Details: serial 12424 error_code 3 request_code 20 minor_code 0)
  (Note to programmers: normally, X errors are reported asynchronously;
   that is, you will receive the error a while after causing it.
   To debug your program, run it with the --sync command line
   option to change this behavior. You can then get a meaningful
   backtrace from your debugger if you break on the gdk_x_error() function.)

The first try (open Calculate, change title, close) worked fine, on the second I got the above crash.

The last entries from datastore.log were:

==> datastore.log <==
1249389163.991101 DEBUG root: datastore.update dbus.String(u'242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3')
1249389163.995086 DEBUG root: IndexStore.flush: False 5
1249389163.998238 DEBUG root: FileStore moving from dbus.String(u'/home/sascha.silbe/.sugar/default/org.laptop.Calculate/instance/1249389163') to u'/home/sascha.silbe/.sugar/default/datastore/24/242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3/data'
1249389164.002992 DEBUG org.laptop.sugar.DataStore: _update_completion_cb() called with <function <lambda> at 0x9a4133c> / <function <lambda> at 0x9a41374>, exc None
1249389164.007408 DEBUG root: optimize u'/home/sascha.silbe/.sugar/default/datastore/checksums/queue/242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3'
1249389164.007943 DEBUG org.laptop.sugar.DataStore: updated 242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3
1249389164.009260 DEBUG root: datastore.get_properties dbus.String(u'242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3')
1249389164.013969 DEBUG root: datastore.find dbus.Dictionary({dbus.String(u'limit'): dbus.Int32(5, variant_level=1), dbus.String(u'order_by'): dbus.Array([dbus.String(u'+timestamp')], signature=dbus.Signature('s'), variant_level=1), dbus.String(u'activity'): dbus.String(u'org.laptop.Calculate', variant_level=1)}, signature=dbus.Signature('sv'))
1249389164.014454 DEBUG root: _parse_query dbus.Dictionary({dbus.String(u'activity'): dbus.String(u'org.laptop.Calculate', variant_level=1)}, signature=dbus.Signature('sv'))
1249389164.016082 DEBUG org.laptop.sugar.DataStore: find(): 0.0016891956329345703
1249389164.017376 DEBUG root: datastore.get_properties dbus.String(u'242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3')
1249389164.021708 DEBUG root: _process_entry_cb processing '242fcbda-1d6c-4d98-b8f2-6b0a4bd3abe3'
1249389224.052541 DEBUG root: IndexStore.flush: True 6

sugar and sugar-toolkit were pristine, sugar-datastore had my WIP prefix support changes (#1090).

[tomeu]

I suspect we are trying to get a preview on a window that has already been destroyed.

[sascha_silbe]

I suspect we are trying to get a preview on a window that has already been destroyed.

Plausible theory, given that it also crashed for me when closing the object picker after encountering #1192.

[alsroot]

Replying to tomeu:

I suspect we are trying to get a preview on a window that has already been destroyed.

looks like nope,
I've commented get_preview() invoking in sugar.activity.activity.Activity.save() and got the same problem

#0  0x00007f8a76e659ca in PyErr_Fetch () from /usr/lib/libpython2.6.so.1.0
(gdb) bt
#0  0x00007f8a76e659ca in PyErr_Fetch () from /usr/lib/libpython2.6.so.1.0
#1  0x00007f8a6c00219c in dbus_py_variant_level_clear () from /usr/lib64/python2.6/site-packages/_dbus_bindings.so
#2  0x00007f8a6c0021f9 in DBusPyStrBase_tp_dealloc () from /usr/lib64/python2.6/site-packages/_dbus_bindings.so
#3  0x00007f8a76dfe6eb in dict_dealloc () from /usr/lib/libpython2.6.so.1.0
#4  0x00007f8a76e1f5b3 in subtype_dealloc () from /usr/lib/libpython2.6.so.1.0
#5  0x00007f8a76dfe6eb in dict_dealloc () from /usr/lib/libpython2.6.so.1.0
#6  0x00007f8a76e1f5b3 in subtype_dealloc () from /usr/lib/libpython2.6.so.1.0
#7  0x00007f8a76dfe6eb in dict_dealloc () from /usr/lib/libpython2.6.so.1.0
#8  0x00007f8a7326c07e in pygobject_dealloc () from /usr/lib64/python2.6/site-packages/gtk-2.0/gobject/_gobject.so
#9  0x00007f8a76e1f516 in subtype_dealloc () from /usr/lib/libpython2.6.so.1.0
#10 0x00007f8a76dd61b3 in instancemethod_dealloc () from /usr/lib/libpython2.6.so.1.0
#11 0x00007f8a73686f82 in child_watch_dnotify () from /usr/lib64/python2.6/site-packages/gtk-2.0/glib/_glib.so
#12 0x00007f8a747f843d in g_source_callback_unref () from /usr/lib/libglib-2.0.so.0
#13 0x00007f8a747f8a25 in g_source_destroy_internal () from /usr/lib/libglib-2.0.so.0
#14 0x00007f8a747f8ea8 in g_main_context_dispatch () from /usr/lib/libglib-2.0.so.0
#15 0x00007f8a747fc5a8 in g_main_context_iterate () from /usr/lib/libglib-2.0.so.0
#16 0x00007f8a747fca9d in g_main_loop_run () from /usr/lib/libglib-2.0.so.0
#17 0x00007f8a72924937 in gtk_main () from /usr/lib/libgtk-x11-2.0.so.0
#18 0x00007f8a72f6ce22 in _wrap_gtk_main () from /usr/lib64/python2.6/site-packages/gtk-2.0/gtk/_gtk.so
#19 0x00007f8a76e5b29d in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0
#20 0x00007f8a76e5b85d in PyEval_EvalFrameEx () from /usr/lib/libpython2.6.so.1.0
#21 0x00007f8a76e5cbc1 in PyEval_EvalCodeEx () from /usr/lib/libpython2.6.so.1.0
#22 0x00007f8a76e5ccd2 in PyEval_EvalCode () from /usr/lib/libpython2.6.so.1.0
#23 0x00007f8a76e777c1 in run_mod () from /usr/lib/libpython2.6.so.1.0
#24 0x00007f8a76e77896 in PyRun_FileExFlags () from /usr/lib/libpython2.6.so.1.0
#25 0x00007f8a76e78ddd in PyRun_SimpleFileExFlags () from /usr/lib/libpython2.6.so.1.0
#26 0x00007f8a76e8534b in Py_Main () from /usr/lib/libpython2.6.so.1.0
#27 0x00007f8a7617da26 in __libc_start_main () from /lib/libc.so.6
#28 0x00000000004006e9 in _start ()

[alsroot]

look like registering wait-for-pid thread triggering this crash

​http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/blobs/master/src/sugar/activity/activityfactory.py#line278

I've commented gobject.child_watch_add and it works w/o crashes

[alsroot]

moving child_watch_add's callback to standalone method fixes this issue(looks like ActivityCreationHandler object is died in place of invoking child_watch_add's callback)

[tomeu]

tracked upstream as ​https://bugs.freedesktop.org/show_bug.cgi?id=23507

[tomeu]

Please push it, though would be good to have a HACK comment referring to the upstream ticket, so we remove it when it gets fixed.

[alsroot]

​http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/0342a24e2db0a29bf9f7de8f66a2b0ac92387845

[benzea]

Reopening for now.

I have tried to reproduce a couple of time today (I removed the above patch for that, but don't think that is really relevant). So, I did get a backtrace with an X crash in the end which looks something like the following (sorry, no proper python bt):

-> X error here
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/sugar/wm.py (37): get_bundle_id
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/model/shell.py (196): get_type
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/model/shell.py (200): is_journal
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/view/buddymenu.py (125): _update_invite_menu
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/view/buddymenu.py (79): _add_buddy_items
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/view/buddymenu.py (51): __init__
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/view/buddyicon.py (33): __init__
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/desktop/meshbox.py (810): _add_alone_buddy
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/desktop/meshbox.py (791): _buddy_added_cb
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/jarabe/model/neighborhood.py (218): _buddy_appeared_cb
/home/benjamin/Projects/sugar-jhbuild/install/lib/python2.5/site-packages/sugar/presence/presenceservice.py (204): _emit_buddy_appeared_signal
-> idle callback handler here

So, what seems to happen is that sugar tries to query the activity boundle of a destroyed X window here. It looks like a very hard to hit race condition here, but it can happen. I'll attach a patch that should work around this (though I have never been able to see a backtrace or even get a crash after I applied it).

The race condition would be:

1. Activity is closed
2. Buddy appears; idle handler registered
3. idle handler _emit_buddy_appeared_signal starts running (sugar-session main loop is blocked)
4. Activities X window is destroyed (sugar-session does not recieve the X event as the main loop blocked)
5. sugar-session rebuilds the invite menu (_update_invite_menu)
6. sugar-session tries to get a property of the destroyed window
7. sugar will/would be notified that the window disappeared and the activity is not the active one anymore

[benzea]

Patch that adds error traps to wm.py

[tomeu]

That's great! What about adding a wrapper function around property_change with the trap? That would remove lots of duplicated code.

[benzea]

ok, newer better

[benzea]

The WM patch is committed too.

​http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/d304f72872fa346dd2c3cedd1d3e508a3aeb5107

[sascha_silbe]

Replying to benzea:

​http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/d304f72872fa346dd2c3cedd1d3e508a3aeb5107

Is it intentional that you pop twice in _property_get_trapped()?

[benzea]

Outch, good catch!

Fixed in ​http://git.sugarlabs.org/projects/sugar-toolkit/repos/mainline/commits/d3c9dc535b710c4bfbba98ba92f15a4bf323dae9

[alsroot]

downstream bug ​http://dev.laptop.org/ticket/9923

[dnarvaez]

Milestone 0.86 deleted