Xpra: Ticket #1456: Server crashes on launching application (inconsistently)

2017-03-01 21:23:10,833 started command 'thunderbird' with pid 7119
[xcb] Unknown sequence number while processing queue
[xcb] Most likely this is a multi-threaded client and XInitThreads has not been called
[xcb] Aborting, sorry about that.

Wed, 01 Mar 2017 18:32:21 GMT - Antoine Martin: status changed; milestone set

• status changed from new to assigned
• milestone set to 2.0

I have seen this very occasionally and indicates a bug in xpra. Unfortunately, I have not been able to reproduce it reliably. If you can reproduce it, please attach the end of the server's "-d all" log.

Wed, 01 Mar 2017 23:22:02 GMT - psycho_zs: attachment set

• attachment set to xcb_error.log

Wed, 01 Mar 2017 23:23:50 GMT - psycho_zs:

Attached last 1k lines of log. With -d all the only new info at the moment of the crash is the python error.

Wed, 01 Mar 2017 23:27:19 GMT - psycho_zs: attachment set

• attachment set to io_error.log

Wed, 01 Mar 2017 23:28:18 GMT - psycho_zs:

Another crash upon connecting, with IO error 11. X server is alive and session can be restored with xpra upgrade

Wed, 01 Mar 2017 23:31:03 GMT - psycho_zs:

...also I can not seem to launch xpra on server anymore, it outputs this:

$ xpra start :100
using systemd-run to wrap 'start' server command
'systemd-run' '--description' 'xpra-start' '--scope' '--user' '/usr/bin/xpra' 'start' ':100' '--systemd-run=no'
Failed to create bus connection: No such file or directory

Remote start works though.

Thu, 02 Mar 2017 04:26:52 GMT - Antoine Martin:

Lots of goodies in those log samples. What distro is this? What exact command lines?

• attachment/ticket/1456/io_error.log shows calls to xsettings just before the IO error and sure enough the X11 calls are unguarded - that's been the case since the very first version of xpra! r15207 fixes that. (will be backported to v1.0.x)
• attachment/ticket/1456/xcb_error.log has more issues in it:
  • r15208 fixes a sound forwarding issue
  • the xcb_xlib_unknown_req_in_deq crash is the same one I had reported in #1430 and failed to reproduce since. It is possible that this is caused by the xsettings issue, but I wouldn't count on it.

Here's a list of significant events leading up to this last crash:

• mouse events (motion and clicks)
• client closes a window and we send the message asking it to close on the server:

  02:14:57,051 client closed window 2 - WindowModel(0x4000b4)
  02:14:57,051 sending WM_DELETE_WINDOW to 0x4000b4
  

• we reset the focus to the world window
• the application unmaps the window and we stop managing it:

  02:14:57,195 x_event_filter event=('xpra-unmap-event', 'xpra-child-unmap-event')/UnmapNotify window=0x4000b4
  02:14:57,197 unmanaging window: WindowModel(0x4000b4) \
      (<gtk.gdk.Window object at 0x7f772463fa00 (GdkWindow at 0x5627d55ea000)> - \
       <gtk.gdk.Window object at 0x7f772463f6e0 (GdkWindow at 0x5627d5597480)>)
  

• we try to cleanup the window state (and get lots of errors since it's gone - which is expected):

  02:14:57,200 XError XError: BadWindow detected while already in unwind; discarding
  

• we tell the client that the window is gone:

  02:14:57,200 add_packet_to_queue(lost-window ...)
  

• the window in focus changes, and so does the cursor so we send the new cursor pixel data to the client:

  02:14:57,233 x_event_filter event=('xpra-focus-out-event', None)/FocusOut took 4.7ms
  02:14:57,233 get_cursor_data() cursor=[1072, 542, 16, 16, 7, 7, 1L, '1024 bytes', '']
  02:14:57,234 get_cursor_data(): default cursor - clearing it
  

• a system tray window is destroyed and we tell the client (I assume thunderbird has some sort of system tray icon):

  02:14:58,819 x_event_filter event=('xpra-destroy-event', None)/DestroyNotify took 0.2ms
  02:14:58,819 x_event_filter event=('xpra-unmap-event', 'xpra-child-unmap-event')/UnmapNotify window=0x4000f3
  02:14:58,819 SystemTray.do_xpra_unmap_event(<X11:UnmapNotify \
      {'delivered_to': '0x4000f3', 'send_event': 0, 'window': '0x4000f3', 'serial': '0x175c', 'type': 18, \
       'display': <gtk.gdk.DisplayX11 object at 0x7f773896fa00 (GdkDisplayX11 at 0x5627d4cf7000)>}>) \
      container window=<gtk.gdk.Window object at 0x7f772463f500 (GdkWindow at 0x5627d5597ea0)>
  02:14:58,821 lost_window: 1 - SystemTrayWindowModel(0x20002e)
  02:14:58,821 add_packet_to_queue(lost-window ...)
  

• again, lots of errors we ignore as we receive events for the already-destroyed window / try to clean it up
• the thunderbird child process terminates:

  02:14:58,835 sigchld(17, <frame object at 0x7f7710003610>)
  02:14:58,835 poll() procinfo list: [ProcInfo({'returncode': None, 'name': 'thunderbird', 'process': <subprocess.Popen object at 0x7f77232b1450>, \
      'pid': 9936, 'dead': False, 'ignore': False, 'callback': None, 'command': ['thunderbird'], 'forget': False})]
  02:14:58,835 add_dead_process(ProcInfo({'returncode': None, 'name': 'thunderbird', 'process': <subprocess.Popen object at 0x7f77232b1450>, \
      'pid': 9936, 'dead': False, 'ignore': False, 'callback': None, 'command': ['thunderbird'], 'forget': False}))
  02:14:58,835 add_dead_process returncode=0, dead=True, callback=None
  02:14:58,835 child 'thunderbird' with pid 9936 has terminated
  

• the client disconnects 4 seconds later:

  02:15:03,579 read thread: eof
  

• a new client connects:

  02:15:05,543 processing packet hello
  

• it requests the server to launch thunderbird:

  02:15:19,201 will process ui packet start-command
  02:15:19,201 start new command: ['start-command', 'thunderbird', 'thunderbird', False, True]
  

It would save me a lot of time to know that I only really care about the last few entries!

Thu, 02 Mar 2017 05:15:27 GMT - psycho_zs:

This was done on Current Debian testing, 64bit, xpra 2.0 r15180. Thunderbird with firetray extension. Server launched with remote xpra start ssh:...:100 -d all At some point it was re-launched after crash with the same X session by xpra upgrade :100 locally on the server, if I remember correctly. (local xpra start does not work).

Thu, 02 Mar 2017 12:29:45 GMT - Antoine Martin: priority changed

• priority changed from major to blocker

I have seen the crash - not sure how to reproduce it reliably yet. Hints would be welcome.

Thu, 02 Mar 2017 17:23:26 GMT - Antoine Martin: owner, status changed

• owner changed from Antoine Martin to psycho_zs
• status changed from assigned to new

@psycho_zs: I am unable to make it crash now that I am ready to investigate it :( I've stopped and restarted thunderbird dozens of times using xpra control :3 start thunderbird. Then I hit a different bug when running debian stretch: we seem to be crashing handling the initial info request, it could be the same bug.

If you can reproduce the thunderbird one easily, can you try:

• apply this to the client:

  --- xpra/client/ui_client_base.py	(revision 15219)
  +++ xpra/client/ui_client_base.py	(working copy)
  @@ -1981,7 +1981,7 @@
           gui_ready()
           if self.tray:
               self.tray.ready()
  -        self.send_info_request()
  +        #self.send_info_request()
       def handshake_complete(self):
           oh = self._on_handshake
  

• running with "--no-tray" to see if that helps
• running r15207 or later to see if that helps

Fri, 03 Mar 2017 15:17:20 GMT - Antoine Martin:

Identified the initial connection problem - hopefully this is the last one: #1430. The patch suggested in comment:8 should avoid causing the crash so easily, but the correct fix will prevent any "info" query from causing crashes.

Fri, 03 Mar 2017 16:21:56 GMT - Antoine Martin:

Bug squashed, see ticket:1430#comment:4. This affected both 1.0.x and trunk.

@psycho_zs: I would really appreciate if you could try to break it again now that I have committed those fixes. I am quite confident the fixes are correct, but there may still be another bug lurking somewhere. To make it easier I have posted updated Debian Stretch beta packages (both trunk and v1.0.4): http://xpra.org/beta.

Fri, 03 Mar 2017 20:51:34 GMT - psycho_zs: attachment set

• attachment set to encoder_error.log

Fri, 03 Mar 2017 20:52:41 GMT - psycho_zs:

no crash yet, local start works. But server drains CPU when client is connected, attached new error spam.

Sat, 04 Mar 2017 01:48:08 GMT - Antoine Martin: status changed; resolution set

• status changed from new to closed
• resolution set to fixed

@psycho_zs: great news - thank you, the error you are seeing is unrelated to the crash (was caused by r15205, fixed in r15222)

I am closing this ticket for now, but feel free to re-open it. I will still look into this as part of #1430.

Note: the only way you can hit this codepath is if you have opengl client rendering disabled... which is not recommended.

Sat, 04 Mar 2017 08:04:28 GMT - psycho_zs:

With opengl on I have redraw issues on window resize (just re-checked on Intel, mesa 17.0.0), so I leave that disabled. Will see if I'm able to catch the crash again.

Sat, 23 Jan 2021 05:24:47 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1456