In message , Martin Gregorie
 writes



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

I agree that what you are describing will give the results that you've
show. However, it isn't what I'm doing (sorry if that wasn't clear).

What I think I'm seeing is :

50th cron run at 09: 00 (no change ) -----> writes 09:00 to the log
51st cron run at 09: 01 (state change) ----> writes 09:07 to the log
52nd cron run at 09: 02 (no change ) ----> writes 09:02 to the log
53rd cron run at 09: 03 (no change  ) ----> writes 09:03 to the log
54th cron run at 09: 04 (no change  ) -----> writes 09:04 to the log

When there has been a hang/delay/whatever, the script timestamps the
state change at a future time, and then continues to log stuff in real
time, which is what is confusing me.  So far as I can see, nothing can
edit the log to add retrospective entries, it just appends to the end
(stdout >> log).

If something is hanging (for want of a better idea of what is happening)
for a few minutes, so be it (that is a different matter), but how does
it mess with the time line ?


To give a fuller example

0619
----------
ble thread started
d2:5f:2d:3c:6f:a6 666f496c5f626561636f6e314df5243c
666f496c5f626561636f6e314df5243c active ffoil_beacon1

0620
----------
ble thread started
Sat  8 Dec 06:27:15 GMT 2018    ffoil_beacon1 has become inactive
666f496c5f626561636f6e314df5243c inactive ffoil_beacon1

0621
----------
ble thread started
666f496c5f626561636f6e314df5243c inactive ffoil_beacon1


There is now an id number applied to each run, and extra timing info, so
it should be possible to see which run is reporting what.
What I'm doing is :

#! /bin/bash

day=$(date +%y%m%d)
time=$(date +%H:%M:%S)
counter=$(cat /home/pi/iBeacon-Scanner/counter)

/home/pi/iBeacon-Scanner/incrementer.sh


logfile=/home/pi/iBeacon-Scanner/output_log_$day.txt

echo "$(date +%H:%M:%S) - $counter" >> $logfile

python /home/pi/iBeacon-Scanner/batch_blescan.py > /tmp/scan.txt

echo -- $(date +%H:%M:%S) $counter Python completed >> $logfile
awk -F, ' {print $1 " " $2 }' /tmp/scan.txt | sort -u >> $logfile

beacon_list=`cat /home/pi/iBeacon-Scanner/beaconlist.txt`

for beacon in $beacon_list
do
    grep $beacon /tmp/scan.txt > /dev/null

    if [ $? -eq 0 ]
    then
        state=`grep $beacon /home/pi/iBeacon-Scanner/state.txt | awk '{
print $2}'`
        if [ "$state" != "active" ]
        then
            sed "s/$beacon inactive/$beacon active/"
/home/pi/iBeacon-Scanner/state.txt >
/home/pi/iBeacon-Scanner/tmp_state.txt
            mv /home/pi/iBeacon-Scanner/tmp_state.txt
/home/pi/iBeacon-Scanner/state.txt
            beacon_name=`grep $beacon /home/pi/iBeacon-Scanner/state.txt
| awk '{ print $3 }'`

            echo $(date) $beacon_name has become active $counter >>
$logfile
        fi
    else
        state=`grep $beacon /home/pi/iBeacon-Scanner/state.txt | awk '{
print $2}'`
        if [ "$state" != "inactive" ]
        then
            sed "s/$beacon active/$beacon inactive/"
/home/pi/iBeacon-Scanner/state.txt >
/home/pi/iBeacon-Scanner/tmp_state.txt
            mv /home/pi/iBeacon-Scanner/tmp_state.txt
/home/pi/iBeacon-Scanner/state.txt
            beacon_name=`grep $beacon /home/pi/iBeacon-Scanner/state.txt
| awk '{ print $3 }'`
        echo $(date) $beacon_name has become inactive $counter >>
$logfile
        fi
    fi
done
cat /home/pi/iBeacon-Scanner/state.txt >> $logfile
echo -- $(date +%H:%M:%S) $counter Completed >> $logfile
echo "" >> $logfile

Originally, the cron job redirected the stdout to a separate logfile
(new one each week), which only recorded the state changes, In an
attempt to get to the bottom of this, I've modded the script to put
everything into one log file (new one each day).

As you can hopefully see, every time I print out a date/time, it is
freshly minted.  Each run should get its own id number, which is
included in the output, which should (hopefully) help trace what is
happening next time the sensor state changes.

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

The Python called by this script gets the status and dumps that to a
file, the script then looks at that file.  So there shouldn't be any
conflicts there.

The sensor in question (currently only one) is a Bluetooth low energy
beacon.  The Python (using the Pi's onboard Bluetooth) is looking to see
what (if any) beacons are active.  It doesn't look for specific beacons,
so I would expect it to behave the same whether there are zero or a
dozen visible.  It prints (to stdout) the details of any beacon it finds
(which seems to be a combination of something looking like a MAC
address, a HEX string and some numbers which I think refer to the signal
strength), and it can see the same beacon several times during the scan,
hence the sort -u above.  As you can see above, I've got a redirect from
stdout to a file. Obviously, the more beacons present, the longer it
will take to complete, and so far as I'm aware nothing else is using the
onboard Bluetooth, so there shouldn't be contention.

Let us see what Monday brings to the log !

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