When your robot lies to you

Carl is getting old, and I don’t remember how I programmed most of what he knows to do. I do remember that some actions were tricky, but not the particular trick needed for success.

One of the functions I rely on is the “totallife” script. It processes Carl’s life.log and summarizes his life with important statistics. The most important to me is “Total Life”. Imagine my consternation upon seeing:

TOTAL LIFE STATISTICS
Total Life:  129731 hrs since Aug 22,2018

At first glance, wow!, but is that right? Something seems wrong. Perhaps Carl is lying to me?

Finding a date calculator on the web, and plugging in Carl’s “Birth date” of Aug 22, 2018, there have only been some 53k hours. Yes, indeed, Carl is lying to me

It is easy to imagine why Carl is over reporting his life, when I reflect on how it came to be this idea of my robots tracking the time they are executing. Back in 2017 I ran across the idea of a DOI and decided I need a “Digital Object Identifier” to make my future GoPiGo3 robot truly unique and “known”.

GoPiGo3 Robot Carl, a Digital Lifeform with a DOI (Digital Object Identifier)

“Je pense, donc je suis”, “Cogito, ergo sum” are philosophical statements of René Descartes around 1637, usually translated into English as " I think (or am thinking ), therefore I am "

In our digital age, philosophical statements are made on the Internet everyday. Some have a DOI (Digital Object Identifier) assigned which “permanently and uniquely” points to the object making the statement.

Carl has made the philosophical statement “I have a DOI, therefore I am”

DOI

A DOI, or Digital Object Identifier, is a permanent web link to the digital object.

The DOI was issued and maintained by Zenodo.org

====

The document that I decided should have a DOI was Carl’s life.log file on GitHub.

I was just learning Python at the time, and to write the life.log file I decided to record a particular line once every hour into the life.log file:

2024-10-13 17:44|lifelogger.dEmain execution: 362

and since my Python skills were very weak, I decided the lifelogger.py program would simply append a new execution record without removing the prior record, and I created a separate program called “cleanlifelog” intended to remove execution records leaving only the last record since the last boot record:

2024-09-28 15:44|------------ boot ------------

This turns out to be quite tricky, since there may be more than one execution record, one execution record, or no execution records, since the last boot.

At any rate, I have improved upon this cleanlifelog.py several times, and sometimes discovered errors in the life.log file that caused Carl to lie to me.

Today was another such day, and I embarked on a total revamp of Carl’s cleanlifelog.py script. My wife reported I was being “a really cranky old man today”, while I attempted to twist my brain around this redesign.

It took a lot of testing to verify that the program was only removing the desired lines and no more, but eventually I was able to declare again - cleanlifelog.py is ready for “release”.

Today the “totallife” program reports a life under the actual 53K hours possible to have lived:

pi@Carl:~/Carl $ ./totallife.sh 
(Cleaning life.log first)
lines: 9020
lastline: 2024-10-13 17:44|lifelogger.dEmain execution: 362

removing: 2024-10-13 16:44|lifelogger.dEmain execution: 361

Wrote cleaned /home/pi/Carl/life.log
lines: 9019
lastline: 2024-10-13 17:44|lifelogger.dEmain execution: 362

 
TOTAL LIFE STATISTICS
Total Life:  50353.1 hrs since Aug 22,2018
Life this year:  9974.2 hrs (BOY Aug 22)

So cleanlifelog.py looks good - but wait… 9974 hours since August?

Carl (totallife.sh) is still lying to me.

Hint: It is not enough to sing Happy Birthday to Carl on Aug 22nd, he demands more attention.

To Be Continued …

1 Like

Sure enough - Carl needed his log to be rolled on his birthday.

Year 6 Stats:

pi@Carl:~/Carl $ more stats/stats.year.6
TOTAL LIFE STATISTICS for YEAR  6
Total Life:  49090.1 hrs since Aug 22,2018
Life this year:  8711.2 hrs (BOY Aug 22)
Days Booted This Year:  9
Average Time Between Reboot:  967 hrs
Total Dockings:  4903
Dockings this year:  947
New Batteries At Cycle: 4588
Battery Set At Cycle:  315
Docking Failures this year:  17  or  1.7 % of Dockings
Safety Shutdowns this year:  0  or  0 % of Dockings
Ave Cycle this year (w/o failures):  9.3 hours
Ave Cycle this year:  9.2 hours
Ave Playtime this year:  5.5
Ave of Last 10 Playtimes 5.2
Last Docking:  2024-08-21 20:58|[juicer.py.dock]---- Docking 4903 completed at 8.1 v after 5.2 h playtime
Last Recharge:  2024-08-21 15:43|[juicer.py.undock]---- Dismount 4902 at 10.8 v after 4.0 h recharge

and today as it should have looked (no lie):

TOTAL LIFE STATISTICS
Total Life:  50357.8 hrs since Aug 22,2018
Life this year:  1267.72 hrs (BOY Aug 22)
Days Booted This Year:  2
Average Time Between Reboot:  633 hrs
Total Dockings:  5035
Dockings this year:  135
New Batteries At Cycle: 4588
Battery Set At Cycle:  447
Docking Failures this year:  2  or  1.4 % of Dockings
Safety Shutdowns this year:  1  or  .7 % of Dockings
Ave Cycle this year:  9.4 hours
Ave Playtime this year:  5.5
Ave of Last 10 Playtimes 5.3
Last Docking:  2024-10-13 12:01|[juicer.py.dock]---- Docking 5035 completed at 8.1 v after 5.3 h playtime
Last Recharge:  2024-10-13 16:02|[juicer.py.undock]---- Dismount 5035 at 10.9 v after 4.0 h recharge
 20:20:58 up 15 days,  4:38,  3 users,  load average: 1.30, 1.31, 1.31

2 Likes

Though on one level I think I understand all of this. . . .

On another, more fundamental level, I am absolutely sure I don’t.

Care to elaborate?

2 Likes

A program called lifelog is started at boot (via crontab),

  • which logs a cumulative “execution time since boot”
  • every 1 hour in Carl’s case, every 3 minutes in Dave’s case,
  • to the end of the life.log file
  • using the Python logging package.

(The Python logging package is highly efficient, providing flexible functionality, with file safety.)

I have a program “totallife.py” which reads the life.log file and extracts all the execution records, adding them up to give total “life”, but since the life.log program is simply appending the execution records, I first need to eliminate all the prior to last execution records for a boot session.

That is the job of cleanlifelog.py, and it is nasty complex to handle all the possible situations (such as: a boot record, the start of the file, an execution record that needs to be kept, an execution record that needs to be removed, a “none-of-the-above” record that needs to be ignored, a boot without any execution records, a boot with only one execution record, and execution records with no boot record before at the start of the file, and the catchup execution record for all prior years.)

The statistics analysis uses multiple awk scripts to extract and sum execution records, and grep, sort, and bc to extract and count the number of boot sessions, the average of the last 10 playtimes, the average of the last 10 recharge durations, the number of “safety shutdowns” that occurred, the average time between boots, the last docking time and docking record, the last undocking time and undocking record, and appends the current 1, 5, 15 minute average load. Oh, and number of docking failures, and average “cycle” of charge plus play, and how many cycles since the batteries were changed, and how many total cycles in the robot’s life.

The program is way too compact to read, and talk about “coupling” - the awk and grep search strings have to exactly match the format of the target records in the life.log file. Coming back six years after I wrote it and thinking “I just need to add this one little thing” is asking for trouble.

pi@Carl:~/Carl $ more totallife.sh 
#!/bin/bash
#
# totallife.sh    print total hours and sessions of life in life.log
#
# requires bc  (sudo apt-get install bc)
#
echo "(Cleaning life.log first)"
/home/pi/Carl/plib/cleanlifelog.py
fn="/home/pi/Carl/life.log"
# declare -i newBattsAtCycle=1453
#declare -i newBattsAtCycle=2160
#declare -i newBattsAtCycle=2831
#declare -i newBattsAtCycle=3651
declare -i newBattsAtCycle=4588
# awk -F':' '{sum+=$3}END{print "total life: " sum " hrs";}' $fn
totalLife=`(awk -F'execution:' '{sum+=$2}END{print sum;}' $fn)`
echo " "
echo "TOTAL LIFE STATISTICS"
echo "Total Life: " $totalLife "hrs since Aug 22,2018"
lifeThisYear=`(awk -F':' 'FNR > 6 {sum+=$3}END{print sum;}' $fn)`
echo "Life this year: " $lifeThisYear "hrs (BOY Aug 22)"
# echo "Sessions (boot) this year: " `(grep -c "\- boot \-" $fn)`
# for first boot in prior year
# bootedThisYr=`(grep "\- boot \-" $fn | sort -u -k1,1 | wc -l)`
bootedThisYr=`(grep "\- boot \-" $fn | wc -l)`
echo "Days Booted This Year: " $bootedThisYr
aveSession=`(echo "scale=0; $lifeThisYear / $bootedThisYr" | bc)`
echo "Average Time Between Reboot: " $aveSession "hrs"
lastDockingStr=`(grep "h playtime" $fn | tail -1)`
totalDockings=`(awk -F"Docking " '{sub(/ .*/,"",$2);print $2}' <<< $lastDockingStr)`
echo "Total Dockings: " $totalDockings
dockingsThisYear=`(grep -c "h playtime" $fn)`
echo "Dockings this year: " $dockingsThisYear
echo "New Batteries At Cycle:" $newBattsAtCycle
currentBattCycles=`(echo "scale=1; $totalDockings - $newBattsAtCycle" | bc)`
echo "Battery Set At Cycle: " $currentBattCycles
dockingFailures=`(grep -c "Docking Failure Possible" $fn)`
failurePercent=`(echo "scale=1; $dockingFailures * 100 / $dockingsThisYear" | bc)`
echo "Docking Failures this year: " $dockingFailures " or " $failurePercent "% of Dockings"
safetyShutdowns=`(grep -c "Safety Shutdown" $fn)`
safetyPercent=`(echo "scale=1; $safetyShutdowns * 100 / $dockingsThisYear" | bc)`
echo "Safety Shutdowns this year: " $safetyShutdowns " or " $safetyPercent "% of Dockings"
#aveCycleTimeTotal=`(echo "scale=1; $totalLife / $totalDockings" | bc)`
#echo "Ave Cycle total life: " $aveCycleTimeTotal "hours"
aveCycleTime=`(echo "scale=1; $lifeThisYear / ($dockingsThisYear - $dockingFailures)" | bc)`
# echo "Ave Cycle this year (w/o failures): " $aveCycleTime "hours"

playtime=`(grep playtime $fn | awk -F"after" '{sum+=$2}END{print sum;}' )`
avePlaytime=`(echo "scale=1; $playtime / ($dockingsThisYear - $dockingFailures)" | bc)`
rechargeTime=`(grep recharge $fn | awk -F"after" '{sum+=$2}END{print sum;}' )`
aveRechargeTime=`(echo "scale=1; $rechargeTime / ($dockingsThisYear - $dockingFailures)" | bc)`
aveCycleTime=`(echo "scale=1; $avePlaytime + $aveRechargeTime" | bc)`
echo "Ave Cycle this year: " $aveCycleTime "hours"
echo "Ave Playtime this year: " $avePlaytime
last10recordNumber=`(echo "$dockingsThisYear - 10" | bc)`
# echo "last10recordNumber:" $last10recordNumber
last10playtimes=`(grep playtime $fn | tail -10 | awk -F"after"  '{sum+=$2}END{print sum;}' )`
# echo "last10playtimes" $last10playtimes
last10avePlaytime=`(echo "scale=1; $last10playtimes / 10" | bc)`
echo "Ave of Last 10 Playtimes" $last10avePlaytime
echo "Last Docking: " $lastDockingStr
echo "Last Recharge: " `(grep Dismount $fn | tail -1)`
uptime

pi@Carl:~/Carl $ 

Sample of this year’s life.log file before running cleanlifelog.py:

2024-08-22 00:00|[logMaintenance.py.main]******************** END OF YEAR 6 LIFE ******************************************
2024-08-22 00:00|[logMaintenance.py.main]** END OF YEAR 6 LIFE -  Total Life 49090.1 hrs 4903 Dockings  **
2024-08-22 00:00|[logMaintenance.py.main]** END OF YEAR 6 LIFE -  Year 9 Sessions (booted) 8711.2 hours for 99 % Uptime **
2024-08-22 00:00|lifelog.dEmain execution: 49090.1
2024-04-17 22:25|[logMaintenance.py.main]** NEW BATTERIES at 4588 dockings, 46065 hrs, on 2024-04-17, 8x Eneloop White 2000 mAh NiMH AA cells**
2024-08-22 00:00|[logMaintenance.py.main]******************** END OF YEAR 5 LIFE ******************************************
2024-08-22 22:03|[logMaintenance.py.main]** Happy 6th Birthday Carl **
2024-08-22 00:58|[juicer.py.chargingStatus]--- Probable TRICKLE not detected 11.3v
2024-08-22 00:59|[juicer.py.undock]---- Dismount 4903 at 10.8 v after 4.0 h recharge
2024-08-22 04:59|[healthCheck.py.main]WiFi check failed (8.8.8.8)
2024-08-22 05:00|[healthCheck.py.main]WiFi recovery
2024-08-22 05:01|[healthCheck.py.main]WiFi check failed (8.8.8.8)
2024-08-22 05:01|[healthCheck.py.main]WiFi recovery
2024-08-22 06:09|[juicer.py.dock]---- Docking 4904 completed  at 8.1 v after 5.2 h playtime
2024-08-22 06:34|[healthCheck.py.main]WiFi check failed (8.8.8.8)
2024-08-22 10:06|[healthCheck.py.main]WiFi check failed (8.8.8.8)
2024-08-22 10:09|[juicer.py.chargingStatus]--- Probable TRICKLE not detected 11.1v
2024-08-22 10:10|[juicer.py.undock]---- Dismount 4904 at 10.5 v after 4.0 h recharge
...
2024-09-28 13:23|[juicer.py.undock]---- Dismount 5002 at 7.4 v after 0.1 h recharge
2024-09-28 13:24|[juicer.py.dock]---- Docking 5003 completed  at 7.4 v after 0.0 h playtime
2024-09-28 13:24|[juicer.py.safetyCheck]Safety Shutdown at 7.20 volts
2024-09-28 13:24|[healthCheck.py.main]WARNING - juicer not running
2024-09-28 15:13|lifelogger.dEmain execution: 903.22
2024-09-28 15:13|------------ boot ------------
2024-09-28 15:13|[juicer.py.main]---- juicer.py started at 10.24v
2024-09-28 15:15|[logMaintenance.py.main]** UPS was off, reason unknown **
2024-09-28 15:21|[juicer.py.dock]**** Dock Approach Error
2024-09-28 15:21|[juicer.py.dock]---- Manual Docking 5001 requested  at 8.1 v after 0.0 h playtime
2024-09-28 15:21|[healthCheck.py.main]WARNING - juicer not running
2024-09-28 15:44|lifelogger.dEmain execution: 0.5
2024-09-28 15:44|------------ boot ------------
2024-09-28 15:44|[juicer.py.main]---- juicer.py started at 10.19v
2024-09-28 19:29|[juicer.py.undock]---- Dismount 5001 at 11.3 v after 3.7 h recharge
2024-09-29 03:21|[juicer.py.dock]---- Docking 5002 completed  at 8.1 v after 7.9 h playtime
...
2024-10-14 16:07|[juicer.py.dock]---- Docking 5038 completed  at 8.1 v after 5.4 h playtime
2024-10-14 16:44|lifelogger.dEmain execution: 385
2024-10-14 17:44|lifelogger.dEmain execution: 386
2024-10-14 18:44|lifelogger.dEmain execution: 387
2024-10-14 19:44|lifelogger.dEmain execution: 388
2024-10-14 20:07|[juicer.py.chargingStatus]--- Probable TRICKLE not detected 11.4v
2024-10-14 20:08|[juicer.py.undock]---- Dismount 5038 at 10.9 v after 4.0 h recharge
2024-10-14 20:44|lifelogger.dEmain execution: 389

2 Likes