In message , Martin Gregorie
 writes
>On Fri, 07 Dec 2018 23:10:26 +0000, Adrian wrote:
>

Thanks for the detailed follow up.

>> 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?
>

No I'm not sure, but it is possible.

>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.
>

The Python code (downloaded from the net) gets the status information
from the sensor (written to a file), my script looks at that file, and
therefore works out if there is a state change.  If I live long enough,
I'll extend the Python to do that as well.

>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.
>

I've modded the script so that it now reports in seconds (as well), and
it will always report the time the script started, when the Python
finishes (the script sets up a couple of variables before running the
Python, so I can't see that there will be a delay there), and when it
finishes.

I take your point about how cron runs each job as required, rather than
putting them in a queue.  However, if I'm doing file redirects rather
than explicitly open the log file at the start of the script, and then
closing it at the end (and thus locking it), I would have thought that
entries should be appearing in chronological order as each one is a
distinct write operation.

>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.
>
>

No, and again thanks for your time.

Adrian
--
To Reply :
replace "bulleid" with "adrian" - all mail to bulleid is rejected
Sorry for the rigmarole, If I want spam, I'll go to the shops
Every time someone says "I don't believe in trolls", another one dies.

--- SoupGate-Win32 v1.05