debug log inhibitor locks when scheduling shutdown

CHANGELOG.md

@@ -5,6 +5,8 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
 ## [Unreleased]
+### Added
+- log shutdown [inhibitor locks](https://www.freedesktop.org/wiki/Software/systemd/inhibit/)
 
 ## [0.1.1] - 2020-06-18
 ### Fixed

systemctl_mqtt/__init__.py

@@ -24,11 +24,12 @@ import socket
 import typing
 
 import dbus
-import paho.mqtt.client
+import dbus.mainloop.glib
 
 # black keeps inserting a blank line above
 # https://pygobject.readthedocs.io/en/latest/getting_started.html#ubuntu-logo-ubuntu-debian-logo-debian
 import gi.repository.GLib  # pylint-import-requirements: imports=PyGObject
+import paho.mqtt.client
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -45,6 +46,32 @@ def _get_login_manager() -> dbus.proxies.Interface:
     return dbus.Interface(object=proxy, dbus_interface="org.freedesktop.login1.Manager")
 
 
+def _log_shutdown_inhibitors(login_manager: dbus.proxies.Interface) -> None:
+    if _LOGGER.getEffectiveLevel() > logging.DEBUG:
+        return
+    found_inhibitor = False
+    try:
+        # https://www.freedesktop.org/wiki/Software/systemd/inhibit/
+        for what, who, why, mode, uid, pid in login_manager.ListInhibitors():
+            if "shutdown" in what:
+                found_inhibitor = True
+                _LOGGER.debug(
+                    "detected shutdown inhibitor %s (pid=%u, uid=%u, mode=%s): %s",
+                    who,
+                    pid,
+                    uid,
+                    mode,
+                    why,
+                )
+    except dbus.DBusException as exc:
+        _LOGGER.warning(
+            "failed to fetch shutdown inhibitors: %s", exc.get_dbus_message()
+        )
+        return
+    if not found_inhibitor:
+        _LOGGER.debug("no shutdown inhibitor locks found")
+
+
 def _schedule_shutdown(action: str) -> None:
     # https://github.com/systemd/systemd/blob/v237/src/systemctl/systemctl.c#L8553
     assert action in ["poweroff", "reboot"], action
@@ -55,6 +82,7 @@ def _schedule_shutdown(action: str) -> None:
         "scheduling %s for %s", action, shutdown_datetime.strftime("%Y-%m-%d %H:%M:%S"),
     )
     shutdown_epoch_usec = int(shutdown_datetime.timestamp() * 10 ** 6)
+    login_manager = _get_login_manager()
     try:
         # $ gdbus introspect --system --dest org.freedesktop.login1 \
         #       --object-path /org/freedesktop/login1 | grep -A 1 ScheduleShutdown
@@ -68,7 +96,7 @@ def _schedule_shutdown(action: str) -> None:
         #       /org/freedesktop/login1 \
         #       org.freedesktop.login1.Manager.ScheduleShutdown \
         #       string:poweroff "uint64:$(date --date=10min +%s)000000"
-        _get_login_manager().ScheduleShutdown(action, shutdown_epoch_usec)
+        login_manager.ScheduleShutdown(action, shutdown_epoch_usec)
     except dbus.DBusException as exc:
         exc_msg = exc.get_dbus_message()
         if "authentication required" in exc_msg.lower():
@@ -78,6 +106,7 @@ def _schedule_shutdown(action: str) -> None:
             )
         else:
             _LOGGER.error("failed to schedule %s: %s", action, exc_msg)
+    _log_shutdown_inhibitors(login_manager)
 
 
 class _Settings:
@@ -174,8 +203,9 @@ def _run(
     # loop_forever attempts to reconnect if disconnected
     # https://github.com/eclipse/paho.mqtt.python/blob/v1.5.0/src/paho/mqtt/client.py#L1744
     mqtt_client.loop_start()
+    # https://dbus.freedesktop.org/doc/dbus-python/tutorial.html#setting-up-an-event-loop
+    dbus.mainloop.glib.DBusGMainLoop(set_as_default=True)
     try:
-        # https://dbus.freedesktop.org/doc/dbus-python/tutorial.html#setting-up-an-event-loop
         gi.repository.GLib.MainLoop().run()
     finally:
         # blocks until loop_forever stops

tests/test_dbus.py

@@ -37,6 +37,66 @@ def test__get_login_manager():
     assert isinstance(login_manager.CanPowerOff(), dbus.String)
 
 
+def test__log_shutdown_inhibitors_some(caplog):
+    login_manager = unittest.mock.MagicMock()
+    login_manager.ListInhibitors.return_value = dbus.Array(
+        [
+            dbus.Struct(
+                (
+                    dbus.String("shutdown:sleep"),
+                    dbus.String("Developer"),
+                    dbus.String("Haven't pushed my commits yet"),
+                    dbus.String("delay"),
+                    dbus.UInt32(1000),
+                    dbus.UInt32(1234),
+                ),
+                signature=None,
+            ),
+            dbus.Struct(
+                (
+                    dbus.String("shutdown"),
+                    dbus.String("Editor"),
+                    dbus.String(""),
+                    dbus.String("Unsafed files open"),
+                    dbus.UInt32(0),
+                    dbus.UInt32(42),
+                ),
+                signature=None,
+            ),
+        ],
+        signature=dbus.Signature("(ssssuu)"),
+    )
+    with caplog.at_level(logging.DEBUG):
+        systemctl_mqtt._log_shutdown_inhibitors(login_manager)
+    assert len(caplog.records) == 2
+    assert caplog.records[0].levelno == logging.DEBUG
+    assert (
+        caplog.records[0].message
+        == "detected shutdown inhibitor Developer (pid=1234, uid=1000, mode=delay): "
+        + "Haven't pushed my commits yet"
+    )
+
+
+def test__log_shutdown_inhibitors_none(caplog):
+    login_manager = unittest.mock.MagicMock()
+    login_manager.ListInhibitors.return_value = dbus.Array([])
+    with caplog.at_level(logging.DEBUG):
+        systemctl_mqtt._log_shutdown_inhibitors(login_manager)
+    assert len(caplog.records) == 1
+    assert caplog.records[0].levelno == logging.DEBUG
+    assert caplog.records[0].message == "no shutdown inhibitor locks found"
+
+
+def test__log_shutdown_inhibitors_fail(caplog):
+    login_manager = unittest.mock.MagicMock()
+    login_manager.ListInhibitors.side_effect = dbus.DBusException("mocked")
+    with caplog.at_level(logging.DEBUG):
+        systemctl_mqtt._log_shutdown_inhibitors(login_manager)
+    assert len(caplog.records) == 1
+    assert caplog.records[0].levelno == logging.WARNING
+    assert caplog.records[0].message == "failed to fetch shutdown inhibitors: mocked"
+
+
 @pytest.mark.parametrize("action", ["poweroff", "reboot"])
 def test__schedule_shutdown(action):
     login_manager_mock = unittest.mock.MagicMock()
@@ -53,7 +113,7 @@ def test__schedule_shutdown(action):
     )
     delay = shutdown_datetime - datetime.datetime.now(tz=_UTC)
     assert delay.total_seconds() == pytest.approx(
-        datetime.timedelta(seconds=4).total_seconds(), abs=0.1,
+        systemctl_mqtt._SHUTDOWN_DELAY.total_seconds(), abs=0.1,
     )
     assert not schedule_kwargs
 
@@ -79,13 +139,14 @@ def test__schedule_shutdown_fail(caplog, action, exception_message, log_message)
     ), caplog.at_level(logging.DEBUG):
         systemctl_mqtt._schedule_shutdown(action=action)
     assert login_manager_mock.ScheduleShutdown.call_count == 1
-    assert len(caplog.records) == 2
+    assert len(caplog.records) == 3
     assert caplog.records[0].levelno == logging.INFO
     assert caplog.records[0].message.startswith("scheduling {} for ".format(action))
     assert caplog.records[1].levelno == logging.ERROR
     assert caplog.records[1].message == "failed to schedule {}: {}".format(
         action, log_message
     )
+    assert "inhibitor" in caplog.records[2].message
 
 
 @pytest.mark.parametrize(