Updating bird.conf to point to non-syslog log file results in incorrect log ownership, no logs written, service failure

[David A. Desrosiers]

This bug is easy to reproduce with the default configuration:

Install bird, 1.6.3-3 for example and start the service with the defaults values. This will create and start the services to run as the 'bird' user and 'bird' group (BIRD_RUN_USER, BIRD_RUN_GROUP)

system(1) will show this working correctly, and relevant bird log entries will appear in /var/log/syslog as expected:

$ sudo service bird status
● bird.service - BIRD Internet Routing Daemon (IPv4)
   Loaded: loaded (/lib/systemd/system/bird.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2020-03-18 10:11:50 EDT; 14s ago
 Main PID: 23485 (bird)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bird.service
           └─23485 /usr/sbin/bird -f -u bird -g bird

Mar 18 10:11:50 hades-nuc systemd[1]: Starting BIRD Internet Routing Daemon (IPv4)...
Mar 18 10:11:50 hades-nuc systemd[1]: Started BIRD Internet Routing Daemon (IPv4).
Mar 18 10:11:50 hades-nuc bird[23485]: Started

Update your /etc/bird/bird.conf and point the 'log' line to something like the following:

  log "/var/log/bird.log" all;

Now restart the bird service:

$ sudo service bird status
● bird.service - BIRD Internet Routing Daemon (IPv4)
   Loaded: loaded (/lib/systemd/system/bird.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Wed 2020-03-18 10:20:44 EDT; 9s ago
  Process: 25376 ExecStart=/usr/sbin/bird -f -u $BIRD_RUN_USER -g $BIRD_RUN_GROUP $BIRD_ARGS $BIRD4_ARGS (code=exited, status=1/FAILURE)
  Process: 25375 ExecStartPre=/usr/sbin/bird -p (code=exited, status=0/SUCCESS)
  Process: 25369 ExecStartPre=/usr/lib/bird/prepare-environment (code=exited, status=0/SUCCESS)
 Main PID: 25376 (code=exited, status=1/FAILURE)

Mar 18 10:20:44 hades-nuc systemd[1]: Stopped BIRD Internet Routing Daemon (IPv4).
Mar 18 10:20:44 hades-nuc systemd[1]: Starting BIRD Internet Routing Daemon (IPv4)...
Mar 18 10:20:44 hades-nuc systemd[1]: Started BIRD Internet Routing Daemon (IPv4).
Mar 18 10:20:44 hades-nuc systemd[1]: bird.service: Main process exited, code=exited, status=1/FAILURE
Mar 18 10:20:44 hades-nuc bird[25376]: bird: /etc/bird/bird.conf, line 8: Unable to open log file `/var/log/bird.log': Permission denied
Mar 18 10:20:44 hades-nuc systemd[1]: bird.service: Failed with result 'exit-code'.

If you look at /var/log/bird.log, you'll see it is owned by 'root:root', not the expected 'bird:bird' as the original socket files (/var/run/bird.ctl, /var/run/bird6.ctl).

This appears to be related to the parsing of bird.conf before privs are dropped and files created.

This can be mitigated with a static workaround in /usr/lib/bird/prepare-environment, but that's a brittle hammer, and not really the right place for this:

diff -u prepare-environment.orig prepare-environment
--- prepare-environment.orig 2020-03-17 15:53:47.122726551 +0000
+++ prepare-environment 2020-03-17 15:51:19.496622613 +0000
@@ -2,11 +2,13 @@ set -eu+BIRD_LOG_FILE=/var/log/bird.log
 BIRD_RUN_DIR=/run/bird
 . /etc/bird/envvars mkdir --parents "$BIRD_RUN_DIR";
+touch "$BIRD_LOG_FILE" if [ -n "$BIRD_RUN_USER" ]; then
     if ! getent passwd $BIRD_RUN_USER >/dev/null; then
@@ -22,7 +24,6 @@
     fi
 fi-chown --silent "$BIRD_RUN_USER:$BIRD_RUN_GROUP" "$BIRD_RUN_DIR"
+chown --silent "$BIRD_RUN_USER:$BIRD_RUN_GROUP" "$BIRD_RUN_DIR" "$BIRD_LOG_FILE"
 chmod 775 "$BIRD_RUN_DIR"
-
 :

Thoughts?

[Ondřej Surý (ondrej)]

That's not specific to bird, any daemon running as non-root have this problem, and usually it's solved by doing:

mkdir -p /var/log/bird
chown bird: /var/log/bird

and configuring the logfile to /var/log/bird/bird.log

I don't think the needs to be fixed at the package level, and on the contrary the prepare-environment should be converted to systemd-tmpfiles.