search

thin-edge / tedge-rugpi-image

thin-edge.io Raspberry Pi 0/1B/2B/3/4/5 image using rugpi for A/B updates
https://thin-edge.io/
2 stars 8 forks source link

mosquitto startup errors leads to the service being disabled by systemd #78

Closed reubenmiller closed 4 months ago

reubenmiller commented 5 months ago

On device startup/boot, the mosquitto service fails to start (maybe because the network is not fully up?), and since the default mosquitto.service settings are to restart as quick as possible, this results in the service tripping the systemd "Start request repeated too quickly", and systemd then gives up trying to start the service.

Below shows how the mosquitto.service looks in this state (notice the "failed" status).

# systemctl status mosquitto.service
× mosquitto.service - Mosquitto MQTT Broker
     Loaded: loaded (/lib/systemd/system/mosquitto.service; enabled; preset: enabled)
     Active: failed (Result: exit-code) since Thu 2024-05-23 08:30:48 BST; 20s ago
       Docs: man:mosquitto.conf(5)
             man:mosquitto(8)
    Process: 890 ExecStartPre=/bin/mkdir -m 740 -p /var/log/mosquitto (code=exited, status=0/SUCCESS)
    Process: 895 ExecStartPre=/bin/chown mosquitto:mosquitto /var/log/mosquitto (code=exited, status=0/SUC>
    Process: 896 ExecStartPre=/bin/mkdir -m 740 -p /run/mosquitto (code=exited, status=0/SUCCESS)
    Process: 899 ExecStartPre=/bin/chown mosquitto:mosquitto /run/mosquitto (code=exited, status=0/SUCCESS)
    Process: 900 ExecStart=/usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf (code=exited, status=1/FAI>
   Main PID: 900 (code=exited, status=1/FAILURE)
        CPU: 15ms

May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is>
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Start request repeated too quickly.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.

The journald logs (since boot) for the mosquitto.service show the failed start attempts:

# journalctl -u mosquitto --boot | cat
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: Starting mosquitto.service - Mosquitto MQTT Broker...
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Loading config file /etc/tedge/mosquitto-conf/c8y-bridge.conf
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Warning: Error resolving bridge address: Temporary failure in name resolution.
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Loading config file /etc/tedge/mosquitto-conf/custom.conf
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Loading config file /etc/tedge/mosquitto-conf/tedge-mosquitto.conf
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Note: It is recommended to replace `message_size_limit` with `max_packet_size`.
May 23 08:30:46 rpi5-d83addab8e9f mosquitto[764]: 1716449446: Loading config file /etc/mosquitto/conf.d/tls-listener.conf
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Main process exited, code=exited, status=1/FAILURE
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 1.
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/c8y-bridge.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Warning: Error resolving bridge address: Temporary failure in name resolution.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/custom.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/tedge-mosquitto.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Note: It is recommended to replace `message_size_limit` with `max_packet_size`.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[858]: 1716449447: Loading config file /etc/mosquitto/conf.d/tls-listener.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/c8y-bridge.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Warning: Error resolving bridge address: Temporary failure in name resolution.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/custom.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/tedge-mosquitto.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Note: It is recommended to replace `message_size_limit` with `max_packet_size`.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[872]: 1716449447: Loading config file /etc/mosquitto/conf.d/tls-listener.conf
May 23 08:30:46 rpi5-d83addab8e9f systemd[1]: Starting mosquitto.service - Mosquitto MQTT Broker...
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Main process exited, code=exited, status=1/FAILURE
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 2.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Starting mosquitto.service - Mosquitto MQTT Broker...
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Main process exited, code=exited, status=1/FAILURE
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 3.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Starting mosquitto.service - Mosquitto MQTT Broker...
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/c8y-bridge.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Warning: Error resolving bridge address: Temporary failure in name resolution.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/custom.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/tedge-mosquitto.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Note: It is recommended to replace `message_size_limit` with `max_packet_size`.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[884]: 1716449447: Loading config file /etc/mosquitto/conf.d/tls-listener.conf
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Main process exited, code=exited, status=1/FAILURE
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 4.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Starting mosquitto.service - Mosquitto MQTT Broker...
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/c8y-bridge.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Warning: Error resolving bridge address: Temporary failure in name resolution.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/custom.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Loading config file /etc/tedge/mosquitto-conf/tedge-mosquitto.conf
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Note: It is recommended to replace `message_size_limit` with `max_packet_size`.
May 23 08:30:47 rpi5-d83addab8e9f mosquitto[900]: 1716449447: Loading config file /etc/mosquitto/conf.d/tls-listener.conf
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Main process exited, code=exited, status=1/FAILURE
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:47 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 5.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: Stopped mosquitto.service - Mosquitto MQTT Broker.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Start request repeated too quickly.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: mosquitto.service: Failed with result 'exit-code'.
May 23 08:30:48 rpi5-d83addab8e9f systemd[1]: Failed to start mosquitto.service - Mosquitto MQTT Broker.

Workaround

You can edit the mosquitto service to define how long it should wait before restarting the service, so that it does not trip the "too many starts" systemd mechanism.

The suggestion was posed from a mosquitto issue: https://github.com/eclipse/mosquitto/issues/2878

  1. Add a drop-in for the mosquitto.service by using:

    systemctl edit mosquitto.service

    And add the following text:

    [Unit]
After=network-online.target
Wants=network-online.target

    Alternatively, the RestartSec property could set prevent quick restarts of mosquitto:

    [Service]
RestartSec=5
reubenmiller commented 5 months ago

Interesting enough, in Yocto, the mosquitto recipe includes a patch for using the network-online.target over network.target. https://patchwork.yoctoproject.org/project/oe/patch/20231006210507.556767-5-peter.marko@siemens.com/

reubenmiller commented 4 months ago

https://github.com/thin-edge/tedge-rugpi-core/pull/23 fixes this issue in the tedge-rugpi-core layer.

tedge-rugpi-image v20240620.1234 includes the fix.