On Fri, 07 Dec 2018 23:10:26 +0000, Adrian wrote:

> As the log is being done by simple redirection, entries should be in
> chronological order.  Only one script is redirecting to the log.
> Therefore I can't see how things can get out of order.  From the full
> log info (which I snipped for brevity) it is obvious when the state
> change is taking place.  So the time at the start of each section (e.g.
> 0630) is correct, but the full timestamp (including the date) is often
> wrong, anything up to 9 minutes out (e.g. if the state change is at
> 0630, the full timestamp will be anything between 0630 and 0639), but
> the next set of log entries will have the correct time (0631 in this
> case).
>
Two things:

1) As the anomalous timestamp seems to be associated with a sensor state
   change, are you quite certain that there is nothing in the sensor
   hardware or the Python code that might get stuck for several minutes
   when its state changes?

2) Do you you know that Python code can read the system clock and so
   can timestamp? See the description of asctime in the time module for
   details. By using this you can add a timestamp to your status
   message without needing to use the date executable.

Explanations and a possible reason for the out of order timestamps follow.

I suspect that (1) is possible: if so, it explains what is happening.
Don't forget that crond starts each cronjob as a separate task and does
not wait for one cronjob to finish before starting another. It has to
work this way because it has no idea how long a job will take to run and
could easily do the unexpected otherwise. As an example, suppose there
are two cron jobs:

- one is a backup run once a day at 01:30 that runs for two hours.

- The other is run every 10 minutes and polls a server for waiting
  messages: it only runs for a second or two at a time.

If crond only ran one job at a time the second job would not run at all
during the backup, which could cause problems, especially if the messages
must be processed immediately and originate worldwide - something like
weather conditions and position reports being monitored by a large
shipping company.

This also means that, if every so often your cron job hangs on a sensor
state change for 9 minutes, then the next 7 or 8 jobs that don't hang can
overtake it and so their messages will appear in the log ahead of the one
that hung. The way your script is currently written, date would read the
time as soon as the script starts and that old time is what will be
prepended to the state message after the hung Python code unsticks and
finally produces its message, with an old timestamp in it, some minutes
later.

The easy way to see whether this is in fact happening is to change your
Python code so it uses the time module to read the timestamp twice, once
as it starts to execute and once just before outputting the message with
both timestamps in it. If the program hangs, the before and after times
will differ by a few minutes. If it doesn't hang, the time will be within
a second of each other (assuming you're only displaying time as hh:mm:ss
rather than as hh:mm:ss.sss). Once that's working you can find out
exactly where the hang is occurring in your code by moving the points
where the timestamps are read until both are the same: the problem must
be in the statement(s) you just excluded from the region between the time
stamps.

In any case, a process that 'ticks' as rapidly as once a minute it would
be better if rewritten round an internal loop with a 60 sleep delay in it
rather than being a series of cron jobs launched 60 seconds apart. It
would look like this:

run = true
while (run == true)
  sleep 60 seconds
  read the sensor
  read the clock
  write yyyy-mm-dd hh:mm:ss
  if (a stop condition is seen)
    run = false

because:

(a) this will make hangups in the program quite obvious

(b) this uses many fewer CPU cycles than having cron run your script:
    to do that it has to load the date executable and your program,
    run them and clean up after them when they exit.

The 'stop condition' can be equally simple - something like checking
whether an empty file is in your home directory and stopping if you
delete it.

I hope the above is useful and didn't trigger any TL:DR reflexes.


--
Martin    | martin at
Gregorie  | gregorie dot org

--- SoupGate-Win32 v1.05