1

I have a Raspberry-Pi based device that takes input from switches and sensors connected to its GPIO, as well as from Arduino connected via TTY serial. The main app managing all this is written in Python3. Here is the startup shell script launcher.sh:

cd /home/pi/ProjectName
venv/bin/python main.py &

And this shell script is registered in crontab for automatic execution at boot:

$ sudo crontab -e

Add to the crontab file:

@reboot sudo su pi /home/pi/ProjectName/launcher.sh >> /home/pi/crontab.log 2>&1

This way, anything that is outputed to stdout or stderr, is caught in the log file.

Rarely, at some strange circumstances the python code fails with uncaught errors that are written in the log file crontab.log. But it is hard to analyze the problem if there is no timestamp of when each line is added to the log file. There is just text, no time information. Also, the log file is reset each time the device is restarted.

I can certainly come up with some dynamic log file name generation from the current datetime, so that is not the main issue. However, I don't know how to set up the logging so that each contribution to the log file is complemented with timestamp.

Kusalananda
  • 333,661
Passiday
  • 315

2 Answers2

1

The world invented tools to do this back in the 1990s. There's no need to reinvent them, poorly, in shell script. They give you strictly size-capped, automatically rotated, rotateable-on-demand, timestamp-named, log files, and timestamps at the beginning of every line of output.

The line timestamps are a non-default option in multilog, s6-log, svlogd, and tinylog, turned on by a command-line option/argument. cyclog adds timestamps unconditionally.

TAI64N timestamps, as added by several of these tools, are (as explained at https://unix.stackexchange.com/a/294276/5132) immune to concerns about timezones and DST changes, are easily machine-processed, and are simply converted to human-readable form by the tai64nlocal filter.

Adapting Kusalananda's cron table entry:

@reboot sudo -u pi sh -c '~pi/ProjectName/launcher.sh 2>&1 | cyclog ~pi/log/crontab'

or:

@reboot sudo -u pi sh -c '~pi/ProjectName/launcher.sh 2>&1 | multilog t ~pi/log/crontab'

There's an inferior way of doing some of this, with the tai64n filter:

@reboot sudo -u pi sh -c '~pi/ProjectName/launcher.sh 2>&1 | tai64n >> ~pi/crontab.log'

However, this does not do the size capping, the automatic rotation, nor the timestamp naming of the log files. Just short-circuit the inevitable reinvention (poorly, in shell script) of logrotate that is the next step from that, and the then having to tackle logrotate's inherent unreliability problems, and skip forward to the 1990s; as above.

Another way to skip forward to the 1990s is to run a service from a service manager, that deals with preventing multiple instances, dæmon context, and proper management mechanisms that allow the service to be stopped/started by the system operator at runtime; rather than using cron and @reboot.

Several service managers have service definition mechanisms that completely obviate any need for your launcher.sh wrapper script and the sudo stuff. Here's a systemd unit (exhibiting one kind of service definition) converted into a nosh service bundle (exhibiting another kind):

% cat ProjectName.service
[Unit]
Description=https://unix.stackexchange.com/a/559920/5132
[Service]
User=pi
WorkingDirectory=/home/pi/%p
ExecStart=venv/bin/python main.py
[Install]
WantedBy=multi-user.target
% 
% system-control convert-systemd-units ./ProjectName.service
% 
% system-control print-service-scripts ./ProjectName
start:#!/bin/nosh
start:#Start file generated from ./ProjectName.service
start:true
stop:#!/bin/nosh
stop:#Stop file generated from ./ProjectName.service
stop:true
run:#!/bin/nosh
run:#Run file generated from ./ProjectName.service
run:#https://unix.stackexchange.com/a/559920/5132
run:envuidgid --supplementary -- pi
run:userenv-fromenv
run:chdir /home/pi/ProjectName
run:setuidgid --supplementary -- pi
run:venv/bin/python main.py
restart:#!/bin/sh
restart:#Restart file generated from ./ProjectName.service
restart:sleep 0.1
restart:exec false  # ignore script arguments
%

For nosh service management, and daemontools-family service management in general, one also sets up a parallel cyclog@ProjectName (or some such) service bundle for the logging (running cyclog, multilog, et al.), and tells the service manager that the latter is the logging service for the former.

Service managers like the nosh per-user-manager, systemd, and Upstart even provide mechanisms for users to configure, run, and manage their own, unprivileged, services.

Further reading

JdeBP
  • 68,745
  • And which of the above would you recommend for the simplest install that works across all platforms nicely? Or the most commonly used. – blissweb Oct 10 '20 at 00:43
0

The log file should not reset when the device is rebooted as you are appending to it. If it is truly reset, then there is some other mechanism that empties or deletes the file.

To redirect to a file with a filename that contains the current timestamp, you may use date to generate the logfile name:

$ date +'/home/pi/crontab-%Y%m%d.log'
/home/pi/crontab-20200101.log

Using this in your crontab schedule:

@reboot sudo -u pi /home/pi/ProjectName/launcher.sh >> "$(date +'/home/pi/crontab-\%Y\%m\%d.log')" 2>&1

Note that each % has to be escaped as \% as they are otherwise special in the crontab file format. Also, I've opted for using sudu -u pi rather than switching to root and then to pi using su. Adding the scheduler to the pi user's crontab would obviously get rid of the need for sudo completely.

This would work provided that your device's clock is synced when the job triggers. If it's not, you get the wrong timestamp. A remedy for that could be to sleep for a bit before actually calling date.

As for getting individually timestamped lines of output from you Python code: This is most likely something that the Python code would have to support by itself.

An easy fix is to output a timestamp to the logfile every now and again from another cron job, maybe once every 15 minutes or so, but this becomes a bit difficult as the logfile name now depends on when the Python script was started.

A solution for that could be to have a symbolic link that points to the current logfile:

@reboot sudo -u pi sh -c 'logfile=$(date +'/home/pi/crontab-\%Y\%m\%d.log'); ln -s -f "$logfile" /home/pi/crontab.log; exec /home/pi/ProjectName/launcher.sh >>"$logfile" 2>&1'

*/15 * * * * date >>/home/pi/crontab.log

This would create /home/pi/crontab.log as a symbolic link to the timestamped logfile before launching your wrapper script (you may want to move the redirection into you actual wrapper script though, as it's becoming a bit unwieldy for a single line cron schedule.

The second job just outputs the result of date into the file that the symbolic link happens to point to at the moment, every 15 minutes.

Kusalananda
  • 333,661