gsm-client goes to infinite loop

[alsroot]

was reported by antoni on #sugar

in unreproducible case, sugar falls to infinite loop which means infinite growing of shell.log

[alsroot]

inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/remainder2.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/equal.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/less.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/print.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/greater.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/ja/numbers/minus.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/images/en/pen/pengroup-new.svg  
  inflating: /home/sugar/Activities/TurtleArt.activity/MANIFEST  
caution: excluded filename not matched:  mimetype
1260839483.103550 WARNING root: No gtk.AccelGroup in the top level window.
1260839483.104550 WARNING root: No gtk.AccelGroup in the top level window.
1260839483.511750 WARNING root: No gtk.AccelGroup in the top level window.
1260839483.546556 WARNING root: No gtk.AccelGroup in the top level window.
1260839483.552881 WARNING root: No gtk.AccelGroup in the top level window.
** (sugar-session:8104): DEBUG: xsmp_save_yourself ('0x92efac0 [sugar-activity 10db60389a5d1a013126083932769027600000081040006]', False)
** (sugar-session:8104): DEBUG: xsmp_save_yourself ('0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]', False)
** (sugar-session:8104): DEBUG: Client '0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]' received InteractRequest(Errors)
** (sugar-session:8104): DEBUG: xsmp_interact ('0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]')
** (sugar-session:8104): DEBUG: Client '0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]' received InteractDone(cancel_shutdown = False)
** (sugar-session:8104): DEBUG: Client '0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]' received SaveYourselfDone(success = True)
** (sugar-session:8104): DEBUG: sms_error_handler (0x91da558, FALSE, 3, c, 32771, 0)
1260839564.337003 WARNING root: No gtk.AccelGroup in the top level window.
1260839564.338023 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.101611 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.115827 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.122890 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.723350 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.737545 WARNING root: No gtk.AccelGroup in the top level window.
1260839603.743837 WARNING root: No gtk.AccelGroup in the top level window.
1260839605.859297 WARNING root: No gtk.AccelGroup in the top level window.
1260839608.641050 WARNING root: No gtk.AccelGroup in the top level window.
1260839608.648127 WARNING root: No gtk.AccelGroup in the top level window.
1260839611.475537 WARNING root: No gtk.AccelGroup in the top level window.
1260839611.491638 WARNING root: No gtk.AccelGroup in the top level window.
1260839611.498610 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.209043 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.227532 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.233924 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.740328 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.755442 WARNING root: No gtk.AccelGroup in the top level window.
1260839617.762318 WARNING root: No gtk.AccelGroup in the top level window.
1260839624.133615 ERROR root: set_active() failed: org.freedesktop.DBus.Error.UnknownMethod: Method "SetActive" with signature "v" on interface "org.laptop.Activity" doesn't exist

1260839626.985905 WARNING root: No gtk.AccelGroup in the top level window.
1260839627.002806 WARNING root: No gtk.AccelGroup in the top level window.
1260839627.009968 WARNING root: No gtk.AccelGroup in the top level window.
1260839627.610604 WARNING root: No gtk.AccelGroup in the top level window.
1260839627.626540 WARNING root: No gtk.AccelGroup in the top level window.
1260839627.633216 WARNING root: No gtk.AccelGroup in the top level window.
1260839632.887034 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
** (sugar-session:8104): DEBUG: ice_io_error_handler (0x91f3fb0)
** (sugar-session:8104): DEBUG: IceProcessMessagesIOError on '0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000]'
** (sugar-session:8104): DEBUG: xsmp_finalize (0x8f3a3b0 [sugar-activity 10db60389a5d1a013126083684587619300000081040000])
1260839637.610684 WARNING root: No gtk.AccelGroup in the top level window.
1260839637.627046 WARNING root: No gtk.AccelGroup in the top level window.
1260839637.633401 WARNING root: No gtk.AccelGroup in the top level window.
1260839642.861609 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
1260839643.823796 WARNING root: No gtk.AccelGroup in the top level window.
1260839643.839427 WARNING root: No gtk.AccelGroup in the top level window.
1260839643.846309 WARNING root: No gtk.AccelGroup in the top level window.
1260839644.349879 WARNING root: No gtk.AccelGroup in the top level window.
1260839644.367564 WARNING root: No gtk.AccelGroup in the top level window.
1260839644.374389 WARNING root: No gtk.AccelGroup in the top level window.
1260839649.083663 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
1260839650.109481 WARNING root: No gtk.AccelGroup in the top level window.
1260839650.126379 WARNING root: No gtk.AccelGroup in the top level window.
1260839650.133070 WARNING root: No gtk.AccelGroup in the top level window.
1260839650.734787 WARNING root: No gtk.AccelGroup in the top level window.
1260839650.750468 WARNING root: No gtk.AccelGroup in the top level window.
1260839650.757279 WARNING root: No gtk.AccelGroup in the top level window.
1260839652.793241 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
1260839654.123734 WARNING root: No gtk.AccelGroup in the top level window.
1260839656.747909 WARNING root: No gtk.AccelGroup in the top level window.
1260839656.754305 WARNING root: No gtk.AccelGroup in the top level window.
1260839657.692275 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
1260839661.202330 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
** (sugar-session:8104): DEBUG: ice_io_error_handler (0x94f6bd0)
** (sugar-session:8104): DEBUG: IceProcessMessagesIOError on '0x92efac0 [sugar-activity 10db60389a5d1a013126083932769027600000081040006]'
** (sugar-session:8104): DEBUG: xsmp_finalize (0x92efac0 [sugar-activity 10db60389a5d1a013126083932769027600000081040006])
1260839661.205341 ERROR root: set_active() failed: org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus)
1260839661.250192 ERROR root: set_active() failed: org.freedesktop.DBus.Error.ServiceUnknown: The name :1.45 was not provided by any .service files
** (sugar-session:8104): DEBUG: accept_ice_connection()
** (sugar-session:8104): DEBUG: New client '0x9305550'
** (sugar-session:8104): DEBUG: Initializing client 0x9305550
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id
** (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
** (sugar-session:8104): DEBUG:   rejected: invalid previous_id

[dsd]

I can reproduce this on a large number of laptops here in Nicaragua, on Sugar 0.82.

To reproduce:

1. Hand out laptops in a school
2. Wait a few months
3. Go to the school
4. Attempt to shut down the XO in the normal way, using the home menu)
5. Nothing happens on-screen (machine does not shut down), sugar log fills up with the errors shown above

[dsd]

Reproduced at Sugarcamp France on Sugar-0.92.3 (XO-1.5)

[dsd]

After working on ​http://dev.laptop.org/ticket/12210 I revisited this with some new knowledge.

The xsmp session manager code currently in sugar does not seem to have the issue that was seen in 12210 (and this code hasn't changed over the last few years). Clients that connect at a late stage do not cause the SM to get confused and delay shutdown, even if they do spam a fair amount in the process. So these looping messages are not the cause of this hang:

* (sugar-session:8104): DEBUG: Client '0x9305550' received RegisterClient(NULL)
* (sugar-session:8104): DEBUG:   rejected: invalid previous_id

Instead, something else must be causing this. Perhaps an already-registered activity that is not responding as expected to the conversation generated during session shutdown.

However, there is something odd going on with those messages. The messages come from this code:

  g_debug ("Client '%s' received RegisterClient(%s)",
           xsmp->description,
	   previous_id ? previous_id : "NULL");

  id = gsm_session_register_client (global_session, client, previous_id);

  if (id == NULL)
    {
      g_debug ("  rejected: invalid previous_id");
      free (previous_id);
      return FALSE;
    }

However, I cannot see a single codepath through gsm_session_register_client() that does not produce a log message (warning or debug). So its odd that we aren't seeing more in the log.

Please attach full logs here (from Sugar start until the point where it goes into the infinite rejected: loop) next time this happens, also stating the sugar version and what was happening (had the user tried to shutdown? were there activities open?).

[tch]

I will put this on low priority until we are able to gather more information.