reentrant call inside logger

[Antoine Martin]

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib64/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
  File "/usr/lib64/python3.7/codecs.py", line 378, in write
    self.stream.write(data)
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib64/python3.7/logging/__init__.py", line 1038, in emit
    self.flush()
  File "/usr/lib64/python3.7/logging/__init__.py", line 1018, in flush
    self.stream.flush()
  File "/usr/lib64/python3.7/site-packages/xpra/child_reaper.py", line 147, in sigchld
    log("sigchld(%s, %s)", signum, frame)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 394, in __call__
    self.log(logging.DEBUG, msg, *args, **kwargs)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 390, in log
    global_logging_handler(self.logger.log, level, msg, *args, **kwargs)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 133, in standard_logging
    log(level, msg, *args, **kwargs)
  File "/usr/lib64/python3.7/logging/__init__.py", line 1449, in log
    self._log(level, msg, args, **kwargs)
  File "/usr/lib64/python3.7/logging/__init__.py", line 1519, in _log
    self.handle(record)
  File "/usr/lib64/python3.7/logging/__init__.py", line 1529, in handle
    self.callHandlers(record)
  File "/usr/lib64/python3.7/logging/__init__.py", line 1591, in callHandlers
    hdlr.handle(record)
  File "/usr/lib64/python3.7/logging/__init__.py", line 905, in handle
    self.emit(record)
  File "/usr/lib64/python3.7/logging/__init__.py", line 1040, in emit
    self.handleError(record)
  File "/usr/lib64/python3.7/logging/__init__.py", line 957, in handleError
    sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Call stack:
  File "/usr/bin/xpra", line 26, in <module>
    sys.exit(main(sys.argv[0], sys.argv))
  File "/usr/lib64/python3.7/site-packages/xpra/scripts/main.py", line 85, in main
    return run_mode(script_file, err, options, args, mode, defaults)
  File "/usr/lib64/python3.7/site-packages/xpra/scripts/main.py", line 411, in run_mode
    return run_server(error_cb, options, mode, script_file, args, current_display)
  File "/usr/lib64/python3.7/site-packages/xpra/scripts/server.py", line 556, in run_server
    return do_run_server(error_cb, opts, mode, xpra_file, extra_args, desktop_display)
  File "/usr/lib64/python3.7/site-packages/xpra/scripts/server.py", line 1186, in do_run_server
    r = app.run()
  File "/usr/lib64/python3.7/site-packages/xpra/server/server_core.py", line 372, in run
    self.do_run()
  File "/usr/lib64/python3.7/site-packages/xpra/server/gtk_server_base.py", line 70, in do_run
    gtk_main()
  File "/usr/lib64/python3.7/site-packages/gi/overrides/Gtk.py", line 1641, in main
    return _Gtk_main(*args, **kwargs)
  File "/usr/lib64/python3.7/site-packages/xpra/server/mixins/audio_server.py", line 186, in configure_pulse
    proc = subprocess.Popen(x, stdin=None, env=env, shell=True, close_fds=True)
  File "/usr/lib64/python3.7/subprocess.py", line 775, in __init__
    restore_signals, start_new_session)
  File "/usr/lib64/python3.7/subprocess.py", line 1476, in _execute_child
    part = os.read(errpipe_read, 50000)
  File "/usr/lib64/python3.7/site-packages/xpra/child_reaper.py", line 148, in sigchld
    self.reap()
  File "/usr/lib64/python3.7/site-packages/xpra/child_reaper.py", line 199, in reap
    self.poll()
  File "/usr/lib64/python3.7/site-packages/xpra/child_reaper.py", line 126, in poll
    self.add_dead_process(procinfo)
  File "/usr/lib64/python3.7/site-packages/xpra/child_reaper.py", line 186, in add_dead_process
    log("child '%s' with pid %s has terminated (ignored)", procinfo.name, procinfo.pid)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 394, in __call__
    self.log(logging.DEBUG, msg, *args, **kwargs)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 390, in log
    global_logging_handler(self.logger.log, level, msg, *args, **kwargs)
  File "/usr/lib64/python3.7/site-packages/xpra/log.py", line 133, in standard_logging
    log(level, msg, *args, **kwargs)
Message: "child '%s' with pid %s has terminated (ignored)"
Arguments: ('pulseaudio-configure-command-0', 13529)

[Antoine Martin]

r21747 should fix this particular race condition.

Not sure we want to do the same thing for the SIGINT handlers with logging, there are many:

• subprocesss_wrapper already wraps the logging call
• src and sink already use idle_add
• client_base: writes to stderr directly, but then signal_cleanup() will call logging
• client_launcher
• confirm_dialog
• open_requests
• pass_dialog
• bug_report
• proxy instance
• server core

Less important since those are only test applications:

• server_commands
• sessions_gui
• start_new_commands
• update_status
• auth_dialog
• gtk gui

In any case, the code could do with some refactoring.

[Antoine Martin]

As per ​Python GTK signal handler not working, we need to use unix_signal_add with GTK3..

Done in r21891.

[migration script]

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