On Sat, 08 Dec 2018 19:52:39 +0000, Adrian wrote:

> In message , Martin Gregorie
>  writes
>>On Fri, 07 Dec 2018 23:10:26 +0000, Adrian wrote:
>>
>>
> Thanks for the detailed follow up.
>
Take a look at my reply to Eli the Bearded  - I think that's a better
explanation of how the use of a back-ticked invocation or using the
$(date) construct inside an otherwise simple script can decouple the
timestamp value from when other stuff in the script actually happened.

Take a look at this script (between the 'datetest start' and 'datetest
end' lines). It shows what I think your cron script does when your
program sees a state change.

================= datetest start =================
#!/bin/bash
echo -n "starting: "; date
dt=$(date)

if [ -n "$1" ]
then
   sleep $1
fi

echo    "dt is:    $dt"
echo -n "ending:   "; date
================= datetest end =================

Save it as as a file called 'datetest, make it executable and then try
running it:

$ datetest

should instantaneously display three lines, all with the same timestamp,
but running it as

$ datetest 10

will force it to take 10 seconds to run (the parameter is the number of
seconds to sleep before continuing). The first two lines should now show
the same timestamp but the third line should show a timestamp that's 10
seconds later than the other two.

What this demonstrates is that by capturing the 'dt' timestamp and then
waiting 'n' seconds before displaying the timestamp, I've forced the 'dt'
message to lie about what the time was when the display was output.

By using the 'backtick' notation round 'date' (just as I used $(date) )
structure I recorded the timestamp when the script had just started. Now,
if anything hangs up (for minutes or even a few seconds) between then and
when the message containing the timestamp is displayed, the script is
reporting the time as earlier than what was when the message was output
(or in your case, appended to the log).

Since it appears that something in your Python program can hang up for up
to for 9 minutes the effect on the log is like this

50th cron run at 09: 00 (no hangup   ) -----> writes 09:00 to the log
51st cron run at 09: 01 (hangs 2 mins) --+
52nd cron run at 09: 02 (no hangup   ) --|--> writes 09:02 to the log
53rd cron run at 09: 03 (no hangup   ) --|--> writes 09:03 to the log
                                         +--> writes 09:01 to the log
54th cron run at 09: 04 (no hangup   ) -----> writes 09:04 to the log

...which is what you're seeing.

Right, now over to you to either prove me wrong or find and fix the
problem!

One suggestion: since you say another process is reading the sensor and
writing its status to a file that your Python program reads, its possible
that there would be an occasional file locking conflicts between the two
processes.

This would occur whenever your Python program tries to read data from the
the end of the file at the same moment as the sensor monitoring program
is adding another reading to the end of the file and so will have the
file open for writing. A read at this point should fail or block because
the OS must prevent 'at end' reads while a sequential file is open for
writing. If it doesn't do that there would be file integrity problems
because the reader can't know where the file end is until the writer has
finished writing data, flushed its write cache and either released the
lock or closed the file.


--
Martin    | martin at
Gregorie  | gregorie dot org

--- SoupGate-Win32 v1.05