Sugar dies upon launching an activity

[bernie]

A kid reported this. I don't have a better description of how to reproduce it, but this is the log:

** (sugar-session:3006): DEBUG: starting phase 1

** (sugar-session:3006): DEBUG: ending phase 1

** (sugar-session:3006): DEBUG: starting phase 2

** (sugar-session:3006): DEBUG: ending phase 2

** (sugar-session:3006): DEBUG: starting phase 3

** (sugar-session:3006): DEBUG: ending phase 3

** (sugar-session:3006): DEBUG: starting phase 4

** (sugar-session:3006): DEBUG: ending phase 4

** (sugar-session:3006): DEBUG: starting phase 5

** (sugar-session:3006): DEBUG: ending phase 5

1281527663.899796 WARNING root: No gtk.AccelGroup in the top level window.
1281527663.915479 WARNING root: No gtk.AccelGroup in the top level window.
1281527664.011118 ERROR root: No gsm connection was set in GConf.
None
:0
1281527665.780888 WARNING root: No gtk.AccelGroup in the top level window.
1281527665.792317 WARNING root: No gtk.AccelGroup in the top level window.
1281527665.803396 WARNING root: No gtk.AccelGroup in the top level window.
1281527665.816016 WARNING root: No gtk.AccelGroup in the top level window.
/usr/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
  super(Connection, self).__init__(*args, **kwargs)

** (sugar-session:3006): WARNING **: Keycode out of bounds: 0 for key F13

** (sugar-session:3006): WARNING **: Keycode out of bounds: 0 for key <shift>F13

** (sugar-session:3006): WARNING **: Keycode out of bounds: 0 for key <control>F13
** (sugar-session:3006): DEBUG: accept_ice_connection()
** (sugar-session:3006): DEBUG: New client '0x97e0b50'
** (sugar-session:3006): DEBUG: Initializing client 0x97e0b50
** (sugar-session:3006): DEBUG: Client '0x97e0b50' received RegisterClient(NULL)
** (sugar-session:3006): DEBUG: Adding new client (null) to session
** (sugar-session:3006): DEBUG: Sending RegisterClientReply to '0x97e0b50 [101a760e27913c42df128152778842164300000030060000]'
** (sugar-session:3006): DEBUG: Sending initial SaveYourself
** (sugar-session:3006): DEBUG: Set properties from client '0x97e0b50 [101a760e27913c42df128152778842164300000030060000]'
** (sugar-session:3006): DEBUG:   Program = 'sugar-activity'
** (sugar-session:3006): DEBUG:   CloneCommand = 'sugar-activity' 
** (sugar-session:3006): DEBUG:   RestartCommand = 'sugar-activity' '--sm-client-id' '101a760e27913c42df128152778842164300000030060000' 
** (sugar-session:3006): DEBUG:   UserID = 'olpc'
** (sugar-session:3006): DEBUG:   ProcessID = '3693'
** (sugar-session:3006): DEBUG:   RestartStyleHint = 0
** (sugar-session:3006): DEBUG: Client '0x97e0b50 [sugar-activity 101a760e27913c42df128152778842164300000030060000]' received SaveYourselfDone(success = True)
** (sugar-session:3006): DEBUG: sms_error_handler (0x93dff60, FALSE, 3, 9, 32771, 0)
1281527813.652238 WARNING root: No gtk.AccelGroup in the top level window.
1281527813.653431 WARNING root: No gtk.AccelGroup in the top level window.
** (sugar-session:3006): DEBUG: ice_io_error_handler (0x96548a8)
** (sugar-session:3006): DEBUG: IceProcessMessagesIOError on '0x97e0b50 [sugar-activity 101a760e27913c42df128152778842164300000030060000]'
** (sugar-session:3006): DEBUG: xsmp_finalize (0x97e0b50 [sugar-activity 101a760e27913c42df128152778842164300000030060000])
1281527882.108493 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
** (sugar-session:3006): DEBUG: accept_ice_connection()
** (sugar-session:3006): DEBUG: New client '0x9179c60'
** (sugar-session:3006): DEBUG: Initializing client 0x9179c60
** (sugar-session:3006): DEBUG: Client '0x9179c60' received RegisterClient(NULL)
** (sugar-session:3006): DEBUG: Adding new client (null) to session
** (sugar-session:3006): DEBUG: Sending RegisterClientReply to '0x9179c60 [101a760e27913c42df128152791287130100000030060001]'
** (sugar-session:3006): DEBUG: Sending initial SaveYourself
** (sugar-session:3006): DEBUG: Set properties from client '0x9179c60 [101a760e27913c42df128152791287130100000030060001]'
** (sugar-session:3006): DEBUG:   Program = 'sugar-activity'
** (sugar-session:3006): DEBUG:   CloneCommand = 'sugar-activity' 
** (sugar-session:3006): DEBUG:   RestartCommand = 'sugar-activity' '--sm-client-id' '101a760e27913c42df128152791287130100000030060001' 
** (sugar-session:3006): DEBUG:   UserID = 'olpc'
** (sugar-session:3006): DEBUG:   ProcessID = '4017'
** (sugar-session:3006): DEBUG:   RestartStyleHint = 0
** (sugar-session:3006): DEBUG: Client '0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]' received SaveYourselfDone(success = True)
** (sugar-session:3006): DEBUG: sms_error_handler (0x9409680, FALSE, 3, 9, 32771, 0)
1281527926.963121 WARNING root: No gtk.AccelGroup in the top level window.
1281527926.964329 WARNING root: No gtk.AccelGroup in the top level window.
1281527929.657757 WARNING root: No gtk.AccelGroup in the top level window.
1281527929.658784 WARNING root: No gtk.AccelGroup in the top level window.
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/sugar/presence/buddy.py", line 205, in _handle_property_changed_signal
    self._properties = self._get_properties_helper()
  File "/usr/lib/python2.6/site-packages/sugar/presence/buddy.py", line 112, in _get_properties_helper
    props = self._buddy.GetProperties(byte_arrays=True)
  File "/usr/lib/python2.6/site-packages/dbus/proxies.py", line 140, in __call__
    **keywords)
  File "/usr/lib/python2.6/site-packages/dbus/connection.py", line 630, in call_blocking
    message, timeout)
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" with signature "" on interface "org.laptop.Sugar.Presence.Buddy" doesn't exist

** (sugar-session:3006): DEBUG: accept_ice_connection()
** (sugar-session:3006): DEBUG: New client '0x97e0ac0'
** (sugar-session:3006): DEBUG: Initializing client 0x97e0ac0
** (sugar-session:3006): DEBUG: Client '0x97e0ac0' received RegisterClient(NULL)
** (sugar-session:3006): DEBUG: Adding new client (null) to session
** (sugar-session:3006): DEBUG: Sending RegisterClientReply to '0x97e0ac0 [101a760e27913c42df128152795055836800000030060002]'
** (sugar-session:3006): DEBUG: Sending initial SaveYourself
** (sugar-session:3006): DEBUG: Set properties from client '0x97e0ac0 [101a760e27913c42df128152795055836800000030060002]'
** (sugar-session:3006): DEBUG:   Program = 'sugar-activity'
** (sugar-session:3006): DEBUG:   CloneCommand = 'sugar-activity' 
** (sugar-session:3006): DEBUG:   RestartCommand = 'sugar-activity' '--sm-client-id' '101a760e27913c42df128152795055836800000030060002' 
** (sugar-session:3006): DEBUG:   UserID = 'olpc'
** (sugar-session:3006): DEBUG:   ProcessID = '4024'
** (sugar-session:3006): DEBUG:   RestartStyleHint = 0
** (sugar-session:3006): DEBUG: Client '0x97e0ac0 [sugar-activity 101a760e27913c42df128152795055836800000030060002]' received SaveYourselfDone(success = True)
** (sugar-session:3006): DEBUG: sms_error_handler (0x9404c58, FALSE, 3, 9, 32771, 0)
1281528213.703081 WARNING root: No gtk.AccelGroup in the top level window.
1281528213.704261 WARNING root: No gtk.AccelGroup in the top level window.
** (sugar-session:3006): DEBUG: ice_io_error_handler (0x9afbac8)
** (sugar-session:3006): DEBUG: IceProcessMessagesIOError on '0x97e0ac0 [sugar-activity 101a760e27913c42df128152795055836800000030060002]'
** (sugar-session:3006): DEBUG: xsmp_finalize (0x97e0ac0 [sugar-activity 101a760e27913c42df128152795055836800000030060002])
1281528213.766399 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
** (sugar-session:3006): DEBUG: xsmp_save_yourself ('0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]', False)
** (sugar-session:3006): DEBUG: Client '0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]' received InteractRequest(Errors)
** (sugar-session:3006): DEBUG: xsmp_interact ('0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]')
** (sugar-session:3006): DEBUG: Client '0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]' received InteractDone(cancel_shutdown = False)
** (sugar-session:3006): DEBUG: Client '0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]' received SaveYourselfDone(success = True)
** (sugar-session:3006): DEBUG: xsmp_die ('0x9179c60 [sugar-activity 101a760e27913c42df128152791287130100000030060001]')

[garycmartin]

sorry, I can see absolutely zero information about the cause, what on earth was the activity!???

[bernie]

Replying to garycmartin:

sorry, I can see absolutely zero information about the cause, what on earth was the activity!???

The kid could not tell, but he said that Sugar dies like this sometimes. Any idea how this DBus error could be triggered?

dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" with signature "" on interface "org.laptop.Sugar.Presence.Buddy" doesn't exist

[bernie]

Also maybe #2064 could be relevant, if we happen to do the same thing that we were doing in the Journal.

[tomeu]

Replying to bernie:

Replying to garycmartin:

sorry, I can see absolutely zero information about the cause, what on earth was the activity!???

The kid could not tell, but he said that Sugar dies like this sometimes. Any idea how this DBus error could be triggered?

dbus.exceptions.DBusException: org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" with signature "" on interface "org.laptop.Sugar.Presence.Buddy" doesn't exist

We seem to ask for the properties of a buddy that is not on the bus any more. Should be relatively harmless.

[bernie]

Replying to tomeu:

We seem to ask for the properties of a buddy that is not on the bus any more. Should be relatively harmless.

Ok. We shouldn't trap the exception to avoid printing a backtrace?

How about this other error?

1281528213.766399 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)

[tomeu]

Replying to bernie:

Replying to tomeu:

We seem to ask for the properties of a buddy that is not on the bus any more. Should be relatively harmless.

Ok. We shouldn't trap the exception to avoid printing a backtrace?

We should listen in the bus so we know when that name is not available any more and update our model. Which is what Aleksey did for the activities.

How about this other error?

1281528213.766399 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)

This is what Aleksey fixed in #2064.

[bernie]

This is very likely a duplicate of #2064.

[bernie]

Tincho could you please attach the logs you collected today? (if they are relevant to this bug and bring anything new)

[bernie]

Closing as duplicate of #2064 as we're obviously not going to diagnose this further.