Failure to get D-Bus Session Bus causes Plover v4.0.0.dev11 to crash upon any notification

[Anodynous]

Describe the bug

Any notification (e.g. due to missing serial port at start, loading of malformed dictionary, etc.) that fails to send over dbus causes Plover to crash after changes introduced in #1496. Prior to the change to plover/oslayer/log_dbus.py they would fail to transmit just the same, but only result in a DBusException being raised instead of causing program to crash.

The issue seems to occur if a dbus instance is reported, but no working SessionBus despite this exists. This is perhaps not the easiest to reproduce, but forcing bus = None for https://github.com/benoit-pierre/plover/blob/5c2dfdb3ca0fc173a055c71008f07fb10d04d0d3/plover/oslayer/log_dbus.py#L88 should trigger the same whenever a notification is emitted.

Error log in Plover v4.0.0.dev11:

2022-08-02 22:00:36,407 [Thread-1-engine] INFO: enable_stroke_logging(True)
2022-08-02 22:00:36,418 [Thread-1-engine] INFO: enable_translation_logging(True)
2022-08-02 22:00:36,425 [Thread-1-engine] INFO: loading system: English Stenotype
2022-08-02 22:00:40,230 [Thread-1-engine] INFO: setting machine: Gemini PR
2022-08-02 22:00:40,242 [Thread-1-engine] WARNING: Can't open serial port
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
FileNotFoundError: [Errno 2] No such file or directory: '/dev/ttyACM0'

During handling of the above exception, another exception occured:

Traceback (most recent call last):
  File"/usr/local/lib/python3.9/dist-packages/plover/machine/base.py", line 215, in start_capture
    self.serial_port = serial.Serial(**self.serial_params)
  File "/usr/local/lib/python3.9/dist-packages/serial/serialutil.py", line 244, in __init__
    self.open()
  File "/usr/local/lib/python3.9/dist-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno2] could not open port /dev/ttyACM0: [Errno 2] No such file or 
directory: '/dev/ttyACM0'
dbus[557]: arguments to dbus_connection_send() were incorrect, assertion "connection != NULL" failed 
in file ../../../dbus/dbus-connection.c line 3307.
This is normally a bug in some application using the D-Bus library.

  D-Bus not built with -rdynamic so unable to print a backtrace
 

Error log in Plover v4.0.0.dev10 (for reference only):

2022-08-02 20:16:26,200 [MainThread] INFO: could not initialize platform gui log
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/plover/log.py", line 101, in setup_platform_handler
    handler = handler_class()
  File "/usr/local/lib/python3.9/dist-packages/plover/oslayer/log_dbus.py", line 22, in __init__
    self._bus = dbus.SessionBus()
  File "/usr/local/lib/python3.9/dist-packages/dbus/_dbus.py", line 212, in __new__
    return Bus.__new__(cls, Bus.TYPE_SESSION, private=private,
  File "/usr/local/lib/python3.9/dist-packages/dbus/_dbus.py", line 102, in __new__
    bus = BusConnection.__new__(subclass, bus_type, mainloop=mainloop)
  File "/usr/local/lib/python3.9/dist-packages/dbus/_dbus.py", line 124, in __new__
    bus = cls._new_for_bus(address_or_type, mainloop=mainloop)
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.Spawn.ExecFailed: /usr/bin/dbus-launch terminated abnormally without any error message
2022-08-02 20:16:26,211 [MainThread] INFO: Plover 4.0.0.dev10+120.g4394ef1
...
2022-08-02 20:16:44,215 [Thread-1-engine] INFO: loaded 5 dictionaries in 13.900s

in dev10 Plover does not crash, but any notification attempted to be sent after failing to spawn the dbus session will produces the same errors as reported in #1490 (comment)

Expected behavior

If a session bus instance cannot be retrieved, raise error similarly as to what is done in case dbus-1 library isn't found. https://github.com/benoit-pierre/plover/blob/5c2dfdb3ca0fc173a055c71008f07fb10d04d0d3/plover/oslayer/log_dbus.py#L54

Operating system

• OS: DietPi v8.6.1
• Plover Version 4.0.0.dev11+23.g991d334

Hardware

• Raspberry Pi Zero W - Running headless for plover-in-the-middle setup (Stenogotchi)

[benoit-pierre]

I can't reproduce (by setting dbus = None after line 88): I get an exception on attempting to log a message, as expected, but no crash. It should not crash, do you have more information about the crash itself?

And what is the value of dbus after line 88? Would this patch take care of the issue:

 plover/oslayer/linux/log_dbus.py | 2 ++
 1 file changed, 2 insertions(+)

diff --git i/plover/oslayer/linux/log_dbus.py w/plover/oslayer/linux/log_dbus.py
index 10a83a7d2..0949fa07d 100644
--- i/plover/oslayer/linux/log_dbus.py
+++ w/plover/oslayer/linux/log_dbus.py
@@ -86,6 +86,8 @@ class DbusNotificationHandler(logging.Handler):
                 raise MemoryError
 
         bus = bus_get(DBUS_BUS_SESSION, None)
+        if bus is None:
+            raise ConnectionError('could not get DBUS session bus')
 
         actions_signature = ctypes.c_char_p(b's')
         hints_signature = ctypes.c_char_p(b'{sv}')

[Anodynous]

Unfortunately haven't figured out a way to get more info on it. The program simply terminates after the last line in the error log.

The value at line 88 is indeed None and the suggested patch successfully prevents Plover from crashing.

2022-08-02 23:48:11,080 [MainThread] INFO: could not initialize platform gui log
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/plover/log.py", line 92, in setup_platform_handler
    handler = NotificationHandler()
  File "/usr/local/lib/python3.9/dist-packages/plover/oslayer/linux/log_dbus.py", line 91, in __init__
    raise ConnectionError('could not get DBUS session bus')
ConnectionError: could not get DBUS session bus
2022-08-02 23:48:11,096 [MainThread] INFO: Plover 4.0.0.dev11+23.g991d334
...
2022-08-02 23:48:27,667 [Thread-1-engine] INFO: enable_stroke_logging(True)
2022-08-02 23:48:27,674 [Thread-1-engine] INFO: enable_translation_logging(True)
2022-08-02 23:48:27,680 [Thread-1-engine] INFO: loading system: English Stenotype
2022-08-02 23:48:31,444 [Thread-1-engine] INFO: setting machine: Gemini PR
2022-08-02 23:48:31,456 [Thread-1-engine] WARNING: Can't open serial port
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/dist-packages/serial/serialposix.py", line 322, in open
    self.fd = os.open(self.portstr, os.O_RDWR | os.O_NOCTTY | os.O_NONBLOCK)
FileNotFoundError: [Errno 2] No such file or directory: '/dev/ttyACM0'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File"/usr/local/lib/python3.9/dist-packages/plover/machine/base.py", line 215, in start_capture
    self.serial_port = serial.Serial(**self.serial_params)
  File "/usr/local/lib/python3.9/dist-packages/serial/serialutil.py", line 244, in __init__
    self.open()
  File "/usr/local/lib/python3.9/dist-packages/serial/serialposix.py", line 325, in open
    raise SerialException(msg.errno, "could not open port {}: {}".format(self._port, msg))
serial.serialutil.SerialException: [Errno2] could not open port /dev/ttyACM0: [Errno 2] No such file or 
directory: '/dev/ttyACM0'
2022-08-02 23:48:31,492 [Thread-1-engine] INFO: starting 'modal_update' extension
2022-08-02 23:48:31,506 [Thread-1-engine] INFO: starting 'stenogotchi_link' extension
...
2022-08-02 23:48:32,189 [Thread-8] WARNING: dictionary 'user.json' loaded with 1 invalid steno errors
...
2022-08-02 23:48:47,881 [Thread-1-engine] INFO: loaded 15 dictionaries in 15.936s