4

I am examining the log of my program, which runs on a Raspbian 9, on an SD card. The program is started and managed by systemd, and the logs are handled by journald.

Occasionally the log contains gaps, such as the one highlighted below: Log fragment with a highlighted part

You can see that a period of almost 24h is not reflected in the log. However, the logic of the software is to log a line once every few minutes, reflecting its current state.

I am also sure that it is not a gap caused by a power outage, because if that were the case, then the first lines on August 27th would have been "start" markers that the program writes when it initializes itself and the periphery it interacts with.

Besides that, my understanding is that journald shows a ----Reboot---- line in the log if the system was booted - I don't see that marker either. Note that persistent logging is enabled and I do see the marker in other spots, where a reboot was expected.

In other words, it seems like those log lines were cut out.

How can such anomalies be explained?

  • What do you see with journalctl --list-boots? – Ingo Sep 1 at 16:43
11

The time gap can be explained because the Raspberry Pi does not have a realtime clock built-in. Raspbian takes effort to make the gap as small as possible and don't always start with 1970-01-01. It stores the date/time from the last shutdown and starts with it. So you will first see this date until the synchronization to the (internet) timeserver is finished. Then the time will jump to the current date/time.

With the journal you do not see the ----Reboot---- delimiter because the journal isn't persistent by default. It is only stored in tmpfs so it will be lost on reboot. There are simply no logs before the last boot that can be delimited by the marker. Raspbian don't log the journal persistent because of storage space consumption. If you want the journal to be persistent then do it with:

rpi ~$ sudo mkdir -p /var/log/journal
rpi ~$ sudo systemd-tmpfiles --create --prefix /var/log/journal

If you enable persistent logging, consider uninstalling rsyslog or any other system-log-daemon, to avoid logging everything twice. With rsyslog running you have the old style log files still available, that are mainly most files in /var/log. For example you will find the same information with journalctl and in /var/log/syslog. And as usual you can configure programs to use rsyslog to log into separate log files.

  • If you want persistent logging, they take up much less space via rsyslog, so it might be better to set journald with storage volatile and capped at 32 MB. If an application is putting out "a line once every few minutes, reflecting its current state" it should really have its own log. This can be configured with rsyslog using tags, but it is simpler to just log directly to your own file, directly or via the service file. – goldilocks Sep 1 at 13:56
  • I updated the question, to indicate that persistent logging is active. Can you clarify the part about uninstalling rsyslog? My software is started by systemd and the service has its own log, which I view with journalctl (it doesn't log to its own file). Does your remark about log duplication assume that the program also keeps a separate log in a file managed by itself? – ralien Sep 1 at 16:01
  • @ralien I have updated the last paragraph in my answer. – Ingo Sep 1 at 16:54
0

Another possible reason for a gap in logs is if the disk fills up, so that further logs are generated but can't be written.

(I doubt that's the cause here, though, and I don't know how journald handles it.  I merely mention it for the benefit of anyone else asking this question!  But I've seen it happen on a non-systemd-based machine.  One symptom is that the last line before the gap can get cut off part-way through, without a newline, so that the next line gets appended to it.)

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.