Creating a systemd timer to regularly pull Git-Repositories and getting to know an uncomfortable systemd/journalctl bug along the way

Christian

8 minutes

April 26, 2024

Creating a systemd timer to regularly pull Git-Repositories and getting to know an uncomfortable systemd/journalctl bug along the way

Photo by Christina Morillo: https://www.pexels.com/photo/white-dry-erase-board-with-red-diagram-1181311/

I have a VM in my LAN which servers as central admin host. There I wanted to create a systemd unit and timer to automatically update my Git-Repositories. The reason is that it happens too often that I push some changes from other machines but forget to pull the repos before I commit my changes done on the admin host.

Sure, stash the commit. Fix any conflicts. No big deal. But still annoying. Therefore: A systemd unit file with a timer that updates the repos every hour and be done with it.

Encountering the bug

While reading the systemd documentation I learned that you can list multiple ExecStart parameters if the service is of Type=oneshot. Then all commands will be executed in sequential order.

Unless Type= is oneshot, exactly one command must be given. When Type=oneshot is used, zero or more commands may be specified. [...] If more than one command is specified, the commands are invoked sequentially in the order they appear in the unit file. If one of the commands fails (and is not prefixed with "-"), other lines are not executed, and the unit is considered failed.

From: https://www.freedesktop.org/software/systemd/man/latest/systemd.service.html#ExecStart=

This seems to be the easiest way to achieve my goal. Just add one ExecStart= line for every Git-Repo, done. For testing I didn't write the timer file. Wanting to verify that the unit file works. And the following unit file works flawlessly.

user@lanadmin:~$ systemctl --user cat git-update
# /home/user/.config/systemd/user/git-update.service
[Unit]
Description=Update git-Repositories
After=network-online.target
Wants=network-online.target

[Service]
# Allows the execution of multiple ExecStart parameters in sequential order
Type=oneshot
# Show status "dead" after commands are executed (this is just commands being run)
RemainAfterExit=no
# git pull = git fetch + git merge
ExecStart=/usr/bin/git -C %h/git/github/chrlau/dotfiles pull
ExecStart=/usr/bin/git -C %h/git/github/chrlau/scripts pull

[Install]
WantedBy=default.target

However, while initially writing it and looking at the output of systemctl --user status git-update I noticed something.

user@lanadmin:~$ systemctl --user status git-update
○ git-update.service - Update git-Repositories
     Loaded: loaded (/home/user/.config/systemd/user/git-update.service; enabled; preset: enabled)
     Active: inactive (dead) since Fri 2024-04-26 22:16:21 CEST; 15s ago
    Process: 39510 ExecStart=/usr/bin/git -C /home/user/git/github/chrlau/dotfiles pull (code=exited, status=0/SUCCESS)
    Process: 39516 ExecStart=/usr/bin/git -C /home/user/git/github/chrlau/scripts pull (code=exited, status=0/SUCCESS)
   Main PID: 39516 (code=exited, status=0/SUCCESS)
        CPU: 40ms

Apr 26 22:16:18 lanadmin systemd[9234]: Starting git-update.service - Update git-Repositories...
Apr 26 22:16:21 lanadmin git[39521]: Already up to date.
Apr 26 22:16:21 lanadmin systemd[9234]: Finished git-update.service - Update git-Repositories.

There should be two log lines with git[pid]: Already up to date. After all we call git two times. But there is only one line. Why!?

At first I considered something like rate-limiting or the de-duplication of identical log messages. But I found nothing. Only an old RedHat Bugreports from 2013 & 2017 about how journalctl can't always catch the necessary process information (cgroup, etc.) from /proc before the process is gone (read: Bug 963620 - journald: we need a way to get audit, cgroup, ... information attached to log messages instead of asynchronously reading them in and Bug 1426152 - Journalctl miss to show logs from unit). Especially with short-running processes this occurred regularly. This can't be the reason, or?

I checked the journal for the unit file. Line still missing.

user@lanadmin:~$ journalctl --user -u git-update
Apr 26 22:16:18 lanadmin systemd[9234]: Starting git-update.service - Update git-Repositories...
Apr 26 22:16:21 lanadmin git[39521]: Already up to date.
Apr 26 22:16:21 lanadmin systemd[9234]: Finished git-update.service - Update git-Repositories.

Then I accidentally executed journalctl without any parameters and...

user@lanadmin:~$ journalctl
[...]
Apr 26 22:16:18 lanadmin systemd[9234]: Starting git-update.service - Update git-Repositories...
Apr 26 22:16:20 lanadmin git[39515]: Already up to date.
Apr 26 22:16:21 lanadmin git[39521]: Already up to date.
Apr 26 22:16:21 lanadmin systemd[9234]: Finished git-update.service - Update git-Repositories.
[...]

There it is. So why does a simple journalctl display both lines, while a systemctl --user status git-update doesn't?

Remembering the bug we just read? journalctl has a verbose mode. This displays all fields for every log line. This should tell us the difference between those to log messages.

At first we have the entry for the Starting git-update.service - Update git-Repositories message. Nothing suspicious here.

user@lanadmin:~$ journalctl -o verbose
Fri 2024-04-26 22:16:18.724396 CEST [s=78cb2a728dda4d579b41ba58b655d4c2;i=6a32;b=859f56a381394260854aeac3b77d87a3;m=1a58bdb7ae0;t=6170593979632;x=ed56438f3a913535]
    PRIORITY=6
    SYSLOG_FACILITY=3
    TID=9234
    SYSLOG_IDENTIFIER=systemd
    _TRANSPORT=journal
    _PID=9234
    _UID=1000
    _GID=1000
    _COMM=systemd
    _EXE=/usr/lib/systemd/systemd
    _CMDLINE=/lib/systemd/systemd --user
    _CAP_EFFECTIVE=0
    _SELINUX_CONTEXT=unconfined
    _AUDIT_SESSION=393
    _AUDIT_LOGINUID=1000
    _SYSTEMD_CGROUP=/user.slice/user-1000.slice/user@1000.service/init.scope
    _SYSTEMD_OWNER_UID=1000
    _SYSTEMD_UNIT=user@1000.service
    _SYSTEMD_USER_UNIT=init.scope
    _SYSTEMD_SLICE=user-1000.slice
    _SYSTEMD_USER_SLICE=-.slice
    _BOOT_ID=859f56a381394260854aeac3b77d87a3
    _MACHINE_ID=e83bb1062b594b79817a5c8a5605f9fd
    _HOSTNAME=lanadmin
    _RUNTIME_SCOPE=system
    CODE_FILE=src/core/job.c
    JOB_TYPE=start
    CODE_LINE=581
    CODE_FUNC=job_emit_start_message
    MESSAGE_ID=7d4958e842da4a758f6c1cdc7b36dcc5
    MESSAGE=Starting git-update.service - Update git-Repositories...
    JOB_ID=10
    USER_INVOCATION_ID=8f476f2ef43245ba89a9cb69a26f8577
    USER_UNIT=git-update.service
    _SOURCE_REALTIME_TIMESTAMP=1714162578724396

Then comes the entry for the first Already up to date. log message. And it's entry is way shorter than the previous log message. No fields regarding systemd are associated.

Fri 2024-04-26 22:16:20.137988 CEST [s=78cb2a728dda4d579b41ba58b655d4c2;i=6a33;b=859f56a381394260854aeac3b77d87a3;m=1a58bf10cb2;t=6170593ad2804;x=730951cbebf4e84a]
    PRIORITY=6
    SYSLOG_FACILITY=3
    _UID=1000
    _GID=1000
    _BOOT_ID=859f56a381394260854aeac3b77d87a3
    _MACHINE_ID=e83bb1062b594b79817a5c8a5605f9fd
    _HOSTNAME=lanadmin
    _RUNTIME_SCOPE=system
    _TRANSPORT=stdout
    _STREAM_ID=36f2542db1e249da8c5c5b1342d065e8
    SYSLOG_IDENTIFIER=git
    MESSAGE=Already up to date.
    _PID=39515
    _COMM=git

And yep, here is the second Already up to date. log message. It contains all fields and this is the message we see, when we display the journal-entries for our git-update.service unit.

Fri 2024-04-26 22:16:21.471040 CEST [s=78cb2a728dda4d579b41ba58b655d4c2;i=6a34;b=859f56a381394260854aeac3b77d87a3;m=1a58c0563ee;t=6170593c17f40;x=2574d8467f36d20]
    PRIORITY=6
    SYSLOG_FACILITY=3
    _UID=1000
    _GID=1000
    _CAP_EFFECTIVE=0
    _SELINUX_CONTEXT=unconfined
    _AUDIT_SESSION=393
    _AUDIT_LOGINUID=1000
    _SYSTEMD_OWNER_UID=1000
    _SYSTEMD_UNIT=user@1000.service
    _SYSTEMD_SLICE=user-1000.slice
    _BOOT_ID=859f56a381394260854aeac3b77d87a3
    _MACHINE_ID=e83bb1062b594b79817a5c8a5605f9fd
    _HOSTNAME=lanadmin
    _RUNTIME_SCOPE=system
    _TRANSPORT=stdout
    SYSLOG_IDENTIFIER=git
    MESSAGE=Already up to date.
    _COMM=git
    _STREAM_ID=cfc8932e3cf9431aa59873d163d624a8
    _PID=39521
    _SYSTEMD_CGROUP=/user.slice/user-1000.slice/user@1000.service/app.slice/git-update.service
    _SYSTEMD_USER_UNIT=git-update.service
    _SYSTEMD_USER_SLICE=app.slice
    _SYSTEMD_INVOCATION_ID=8f476f2ef43245ba89a9cb69a26f8577

Great. So how to fix this? Yeah, I can't. Unless I can make the git-process running longer there is no real solution. I tried adding ExecStart=/usr/bin/sleep 1 after each git command, but that of course didn't change anything. As sleep is a different process.

Now I'm left with the following situation: Sometimes both log entries are logged correctly with all fields. Sometimes just one (either the first or second one). And rarely none is logged at all. Then all I have are the standard Starting git-update.service - Update git-Repositories. and Finished git-update.service - Update git-Repositories... log messages which are sent via systemd when a unit file is started and when it finishes.

Beautiful. Just beautiful. I mean.. The syslog facility, identifier and priority is logged each time. So yeah, that's actually a reason for good old rsyslog.

A somewhat of a solution?

The best advise I can currently give is: If you have short lived processes started via systemd and it's important you can easily view all log messages:

Make sure ForwardToSyslog=yes is set in /etc/systemd/journald.conf. Note that the default values are usually listed as comments. So if the line #ForwardToSyslog=yes is present, you should be fine
Install rsyslog or any other traditional syslog service
Configure it to store your log messages in a separate logfile or let it go to /var/log/messages
Don't forget to configure logrotate (or some other sort of logfile rotating) for all logfiles created by rsyslog 😉

I just learned to always execute a plain journalctl during troubleshooting sessions just to make sure that I spot messages from short running processes.

And what about the timer?

This is the timer file I use. It runs once every hour.

user@lanadmin:~$ systemctl --user cat git-update.timer
# /home/user/.config/systemd/user/git-update.timer
[Unit]
Description=Update git-repositories every hour

[Timer]
# Documentation: https://www.freedesktop.org/software/systemd/man/latest/systemd.time.html#Calendar%20Events
OnCalendar=*-*-* *:00:00
Unit=git-update.service

[Install]
WantedBy=default.target

After creating the file you need to enable and start it.

user@lanadmin:~$ systemctl --user enable git-update.timer
Created symlink /home/user/.config/systemd/user/default.target.wants/git-update.timer → /home/user/.config/systemd/user/git-update.timer.

user@lanadmin:~$ systemctl --user start git-update.timer

Using systemctl --user list-timers we can verify that the timer is scheduled to run.

user@lanadmin:~$ systemctl --user list-timers
NEXT                         LEFT       LAST PASSED UNIT                   ACTIVATES
Sun 2024-04-28 16:00:00 CEST 49min left -    -      git-update.timer git-update.service

1 timers listed.
Pass --all to see loaded but inactive timers, too.