Janus blocked from restarting if STUN server is unavailable

Start with debian-pkg/usr/share/tinypilot/janus.service, then inspect the Python code path that invokes /usr/sbin/service janus restart. Reproduce the repeated-failure behavior with systemctl and journalctl, and compare it with the documented systemctl reset-failed workaround. Done means Janus can be restarted after a failed STUN startup without waiting for systemd or manually resetting the failed state.

We already discovered the (rather unfortunate) Janus startup behavior, where Janus would refuse to come up altogether if the STUN server is not available/reachable at startup time, or if the network server is not available yet.

Steps to reproduce

• Configure Janus with an invalid or unreachable STUN server
• Restart the Janus service to apply changes (systemctl restart janus)
• Open the Janus service logs (journalctl -f -u janus) and watch systemd trying to start Janus for 20 times
• Then systemd flags Janus as failed
• Now, configure Janus with a valid and reachable STUN server
• Restart the Janus service

Systemd now refuses to restart Janus, since it’s flagged as failed. Only after a grace period of a few minutes, systemd accepts startup requests again.

So during failed state, you wouldn’t even be able to revoke the STUN config, or make any other config change to Janus.

More info

With this fix we implemented a workaround that focusses on the scenario with the network service.

There is another problem resulting from this, however: if the user specifies a STUN server that is either not present at all, or down for a longer time, then systemd will try to start Janus 20 times.

https://github.com/tiny-pilot/tinypilot/blob/0a03d2caf54aa083ef66c1606e28321f41aca781/debian-pkg/usr/share/tinypilot/janus.service#L5-L7

After 20 failures, systemd flags the Janus service as failed, so issuing systemctl restart janus or the like doesn’t have any effect.

You can see this in the logs below: at 16:15:11, it tries to start Janus for the 20th time, which fails at 16:15:17. After that, I periodically and manually try to restart the service via /usr/sbin/service janus restart (which is the command we normally use from our Python code), e.g. at 16:15:17, then at 16:16:09, then at 16:16:37, and so on. All those invocations fail right away, because the service is in failed state.

At 16:18:13, however, systemd starts to accept start requests again. Note that this is roughly 180 seconds / 3 minutes after the 20th automated (but failed) startup attempt.

The only way to bypass this blockage and recover the service is by manually issuing systemctl reset-failed janus. That immediately revokes the failed flag. This functionality isn’t available via /usr/sbin/service, however.

Either way, I’m not sure we have fully understood all the different start intervals and retry settings of systemd.

Oct 05 16:15:11 raspberrypi janus[4585]: ---------------------------------------------------
Oct 05 16:15:11 raspberrypi janus[4585]:   Starting Meetecho Janus (WebRTC Server) v1.0.1
Oct 05 16:15:11 raspberrypi janus[4585]: ---------------------------------------------------
Oct 05 16:15:11 raspberrypi janus[4585]: Checking command line arguments...
Oct 05 16:15:11 raspberrypi janus[4585]: Debug/log level is 4
Oct 05 16:15:11 raspberrypi janus[4585]: Debug/log timestamps are disabled
Oct 05 16:15:11 raspberrypi janus[4585]: Debug/log colors are disabled
Oct 05 16:15:11 raspberrypi janus[4585]: Using 192.168.2.2 as local IP...
Oct 05 16:15:11 raspberrypi janus[4585]: Token based authentication disabled
Oct 05 16:15:11 raspberrypi janus[4585]: Initializing recorder code
Oct 05 16:15:11 raspberrypi janus[4585]: Initializing ICE stuff (Full mode, ICE-TCP candidates disabled, half-trickle, IPv6 support disabled)
Oct 05 16:15:11 raspberrypi janus[4585]: STUN server to use: stun.ucsb.edu:3478
Oct 05 16:15:11 raspberrypi janus[4585]:   >> 128.111.24.49:3478 (IPv4)
Oct 05 16:15:11 raspberrypi janus[4585]: Testing STUN server: message is of 20 bytes
Oct 05 16:15:16 raspberrypi janus[4585]: [FATAL] [ice.c:janus_ice_test_stun_server:1078] No response to our STUN BINDING test
Oct 05 16:15:16 raspberrypi janus[4585]: [FATAL] [janus.c:main:4988] Invalid STUN address stun.ucsb.edu:3478
Oct 05 16:15:16 raspberrypi janus[4584]: Error launching Janus (error code 1), check the logs for more details
Oct 05 16:15:16 raspberrypi systemd[1]: janus.service: Control process exited, code=exited, status=1/FAILURE
Oct 05 16:15:16 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:15:16 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:15:17 raspberrypi systemd[1]: janus.service: Scheduled restart job, restart counter is at 20.
Oct 05 16:15:17 raspberrypi systemd[1]: Stopped Janus WebRTC gateway.
Oct 05 16:15:17 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:15:17 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:15:17 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:09 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:09 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:09 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:37 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:37 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:37 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:41 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:41 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:41 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:48 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:48 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:48 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:52 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:52 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:52 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:16:55 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:16:55 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:16:55 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:02 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:02 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:02 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:06 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:06 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:06 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:09 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:09 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:09 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:18 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:18 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:18 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:25 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:25 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:25 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:34 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:34 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:34 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:51 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:51 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:51 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:17:58 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:17:58 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:17:58 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:18:07 raspberrypi systemd[1]: janus.service: Start request repeated too quickly.
Oct 05 16:18:07 raspberrypi systemd[1]: janus.service: Failed with result 'exit-code'.
Oct 05 16:18:07 raspberrypi systemd[1]: Failed to start Janus WebRTC gateway.
Oct 05 16:18:13 raspberrypi systemd[1]: Starting Janus WebRTC gateway...
Oct 05 16:18:13 raspberrypi janus[4722]: Janus version: 1001 (1.0.1)
Oct 05 16:18:13 raspberrypi janus[4722]: Janus commit: not-a-git-repo
Oct 05 16:18:13 raspberrypi janus[4722]: Compiled on:  Mon May  2 06:19:49 UTC 2022
Oct 05 16:18:13 raspberrypi janus[4722]: Running Janus as a daemon
Oct 05 16:18:13 raspberrypi janus[4723]: Logger plugins folder: /usr/lib/arm-linux-gnueabihf/janus/loggers
Oct 05 16:18:13 raspberrypi janus[4723]: [WARN] Logger plugin 'libjanus_jsonlog.so' has been disabled, skipping...
Oct 05 16:18:13 raspberrypi janus[4723]: ---------------------------------------------------
Oct 05 16:18:13 raspberrypi janus[4723]:   Starting Meetecho Janus (WebRTC Server) v1.0.1
Oct 05 16:18:13 raspberrypi janus[4723]: ---------------------------------------------------
Oct 05 16:18:13 raspberrypi janus[4723]: Checking command line arguments...
Oct 05 16:18:13 raspberrypi janus[4723]: Debug/log level is 4
Oct 05 16:18:13 raspberrypi janus[4723]: Debug/log timestamps are disabled
Oct 05 16:18:13 raspberrypi janus[4723]: Debug/log colors are disabled
Oct 05 16:18:13 raspberrypi janus[4723]: Using 192.168.2.2 as local IP...
Oct 05 16:18:13 raspberrypi janus[4723]: Token based authentication disabled
Oct 05 16:18:13 raspberrypi janus[4723]: Initializing recorder code