Cron job to detect when system power is lost returning invalid timings

Question

We are having issues with our electrics, so I wrote a simple bash script to try to log when the events were happening. I've created a cron job that runs every minute to run the script.

The idea of the script is quite simple, write the timestamp to /tmp/powerlast.tmp. If next time the script runs, the gap in time is greater than 90 seconds append an entry using the $powerlast value to the powerfailure.csv file.

I'm getting some strange results, for example at on 24th Dec @ 11:50am the electrics tripped, but the script is telling me that it occurred at 11:20am - this is wrong.

#!/bin/bash
powercsv=~/powerfailure.csv
powerlast=/tmp/powerlast.tmp
frequency=60                  # seconds
margin=$(($frequency+($frequency/2)))
if [ ! -f "$powercsv" ]; then
  echo "timestamp,weekofyear,dayofyear,day,date,month,year,hour,minute" > "$powercsv"
fi
if [ ! -f "$powerlast" ]; then
  echo "4133980799" > "$powerlast"
fi
last=$(($(cat "$powerlast"))) # seconds since epoch
now=$(($(date +%s)))          # seconds since epoch
lastdate=$(date -d @$last)
nowdate=$(date -d @$now)
if [ $now -lt $last ]; then
  # first run ever
  echo "$now" > "$powerlast"
else
  # aim is to detect gaps greater than the run frequency.
  # echo "margin $margin frequency $frequency"
  echo "$now" > "$powerlast"
  gap=$(($now-$last))
  if [ $gap -gt $margin ]; then
    echo "$nowdate: Power interruption detected at $lastdate! $gap exceeds $margin second limit."
    weekofyear=$(date -d @$last +%V)
    dayofyear=$(date -d @$last +%j)
    day=$(date -d @$last +%a)
    date=$(date -d @$last +%d)
    month=$(date -d @$last +%m)
    year=$(date -d @$last +%y)
    hour=$(date -d @$last +%H)
    minute=$(date -d @$last +%M)
    echo "$last,$weekofyear,$dayofyear,$day,$date,$month,$year,$hour,$minute" >> "$powercsv"
  fi
fi

I scheduled a task to run * * * * * /home/usr/powerfailure/powerfailure.sh via crontab -e

I've checked the file that I use to track the last uptime and it seems to be OK (I checked my clock and it's the same).

$ grep  -Eo '^[0-9]+' /tmp/powerlast.tmp | while read x; do date -d @$x; done
Tue Dec 24 12:41:02 GMT 2019

Oddly, all my entries seem to be logging approximately 20 past the hour.

$ grep -Eo '^[0-9]+' powerfailure.csv | while read x; do date -d @$x; done
Fri Dec 20 13:03:02 GMT 2019
Sat Dec 21 10:18:01 GMT 2019
Sat Dec 21 11:18:02 GMT 2019
Sat Dec 21 19:20:02 GMT 2019
Sun Dec 22 02:19:01 GMT 2019
Mon Dec 23 14:21:02 GMT 2019
Tue Dec 24 07:20:02 GMT 2019
Tue Dec 24 11:20:01 GMT 2019

I checked the /var/log/syslog and found some odd timestamp ordering in there, so I think this may be to blame, but I don't know why it's doing this.

Dec 24 11:45:01 raspberrypi CRON[9915]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:46:02 raspberrypi CRON[9976]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:47:01 raspberrypi CRON[10011]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:17:46 raspberrypi cron[324]: (CRON) INFO (pidfile fd = 3)
Dec 24 11:17:46 raspberrypi cron[324]: (pi) ORPHAN (no passwd entry)
Dec 24 11:17:46 raspberrypi cron[324]: (CRON) INFO (Running @reboot jobs)
Dec 24 11:18:01 raspberrypi CRON[737]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:19:01 raspberrypi CRON[1459]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:20:01 raspberrypi CRON[2308]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:20:01 raspberrypi CRON[2313]: (smmsp) CMD (test -x /etc/init.d/sendmail && test -x /usr/share/sendmail/sendmail && test -x /usr/lib/sm.bin/sendmail && /usr/share/sendmail/sendmail cron-msp)
Dec 24 11:52:35 raspberrypi CRON[3237]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:53:01 raspberrypi CRON[3657]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)
Dec 24 11:54:01 raspberrypi CRON[4600]: (usr) CMD (/home/usr/powerfailure/powerfailure.sh)

mrswadge · Accepted Answer · 2020-01-08T10:08:14.580

I moved the tracking file out of /tmp and altered my script to use touch instead. The script now tracks the modified date of the file instead of the content. I'm still unclear why it wasn't working as intended, but this system is working exactly as intended.

#!/bin/bash
powerdir=~/powerfailure
mkdir -p "$powerdir"
powercsv="$powerdir/powerfailure.csv"
powertouch="$powerdir/powerlast.touch"
frequency=60                  # seconds
margin=$(($frequency+($frequency/2)))
if [ ! -f "$powercsv" ]; then
  echo "timestamp,weekofyear,dayofyear,day,date,month,year,hour,minute" > "$powercsv"
fi
if [ ! -f "$powertouch" ]; then
  touch "$powertouch"
fi
last=$(date -r "$powertouch" +%s) # seconds since epoch
now=$(($(date +%s)))              # seconds since epoch
lastdate=$(date -d "@$last")
nowdate=$(date -d "@$now")
# echo "Last: $last, Now: $now, Last Date: $lastdate, Now Date: $nowdate"
if [ $now -lt $last ]; then
  # first run ever
  echo "$now" > "last"
  echo "Reset power last variable"
  echo "Reported: $(date)"
  echo "Last: '$last' -> $(date -d "@$last")"
  echo "Current: $now' -> $(date -d "@$now")"
else
  # aim is to detect gaps greater than the run frequency.
  # echo "margin $margin frequency $frequency"
  touch "$powertouch"
  gap=$(($now-$last))
  if [ $gap -gt $margin ]; then
    echo "Reported: $(date)"
    echo "Last: '$last' -> $(date -d "@$last")"
    echo "Current: '$now' -> $(date -d "@$now")"
    echo "$nowdate: Power interruption detected at $lastdate! $gap exceeds $margin second limit."
    weekofyear=$(date -d "@$last" +%V)
    dayofyear=$(date -d "@$last" +%j)
    day=$(date -d "@$last" +%a)
    date=$(date -d "@$last" +%d)
    month=$(date -d "@$last" +%m)
    year=$(date -d "@$last" +%y)
    hour=$(date -d "@$last" +%H)
    minute=$(date -d "@$last" +%M)
    echo "$last,$weekofyear,$dayofyear,$day,$date,$month,$year,$hour,$minute" >> "$powercsv"
  fi
fi

Cron job to detect when system power is lost returning invalid timings

1 Answers1