fixed delay time bug

raspberry/startup_safechicken.sh

@@ -14,4 +14,4 @@ if [ -e log/application.log ]; then
 fi
 
 chown -R pi:pi log
-su pi -c 'source venv/bin/activate && /bin/bash -c "python3 -m safechicken.main config.json 2>&1 >>log/application.log &"'
+su pi -c 'source venv/bin/activate && /bin/bash -c "python3 -m safechicken.main config.json --logfile log/application.log &"'

safechicken/iocontrol.py

@@ -5,6 +5,7 @@
 from gpiozero import LED, DigitalOutputDevice, DigitalInputDevice, Device
 from gpiozero.pins.mock import MockFactory
 import threading
+import logging
 
 import os
 if not os.uname()[4].startswith("arm"):
@@ -72,21 +73,21 @@ def get_door_state_log(self):
         return copy.deepcopy(self.door_closed_log)
 
     def on_door_closed(self):
-        print('input: door closed')
+        logging.info('input: door closed')
         self.door_closed_log.insert(0, {'state': 'open', 'datetime': datetime.now().isoformat(timespec='minutes')})
         if len(self.door_closed_log) > 10:
             del self.door_closed_log[-1]
 
     def on_door_not_closed(self):
-        print('input: door NOT closed/opening/open')
+        logging.info('input: door NOT closed/opening/open')
         self.door_closed_log.insert(0, {'state': 'close', 'datetime': datetime.now().isoformat(timespec='minutes')})
         if len(self.door_closed_log) > 10:
             del self.door_closed_log[-1]
 
     def _check_and_open(self, reason):
         self.out_close_command.off()
         self.out_open_command.on()
-        print('io: open command, reason {0}'.format(reason))
+        logging.info('io: open command, reason {0}'.format(reason))
         self._start_clear_timer()
 
         self.last_command_list.insert(0, {'command': 'open', 'datetime': datetime.now().isoformat(timespec='minutes'), 'reason': reason})
@@ -96,7 +97,7 @@ def _check_and_open(self, reason):
     def _check_and_close(self, reason):
         self.out_open_command.off()
         self.out_close_command.on()
-        print('io: close command, reason {0}'.format(reason))
+        logging.info('io: close command, reason {0}'.format(reason))
         self._start_clear_timer()
 
         self.last_command_list.insert(0, {'command': 'close', 'datetime': datetime.now().isoformat(timespec='minutes'), 'reason': reason})
@@ -112,7 +113,7 @@ def _start_clear_timer(self):
         self.clear_timer.start()
 
     def _clear_command_out(self):
-        print('io: clear command out')
+        logging.info('io: clear command out')
         self.out_open_command.off()
         self.out_close_command.off()
 

safechicken/main.py

@@ -3,6 +3,7 @@
 import json
 import time
 import subprocess
+import logging
 from copy import deepcopy
 
 from safechicken import timecontrol, mqttclient, iocontrol
@@ -28,30 +29,30 @@ def update_timesync_flag(self):
 
             ntp_line = [line for line in res.decode("utf-8").splitlines() if 'Synchronized' in line]
             if '=yes' in ntp_line:
-                print('timesync working, system clock set: {0}'.format(datetime.datetime.now().isoformat()))
+                logging.info('timesync working, system clock set: {0}'.format(datetime.datetime.now().isoformat()))
                 self.systemtime_synced = True
                 return
 
         except Exception as e:
             if not self.timesync_err_reported:
-                print('Error executing timesync query command: {0}'.format(e))
+                logging.warning('Error executing timesync query command: {0}'.format(e))
             self.timesync_err_reported = True
 
         # self.timesync_err_reported = False -> try old style
         try:
             command = ['timedatectl', 'status']
-            print('trying old style time sync command... {0}'.format(command))
+            logging.info('trying old style time sync command... {0}'.format(command))
             res = subprocess.check_output(command)
 
             ntp_line = [line for line in res.decode("utf-8").splitlines() if 'synchronized' in line]
             if any('yes' in s for s in ntp_line):
-                print('timesync working, system clock set: {0}'.format(datetime.datetime.now().isoformat()))
+                logging.info('timesync working, system clock set: {0}'.format(datetime.datetime.now().isoformat()))
                 self.systemtime_synced = True
                 return
 
         except Exception as e:
             if not self.timesync_err_reported:
-                print('Error executing timesync query command: {0}'.format(e))
+                logging.warning('Error executing timesync query command: {0}'.format(e))
             self.timesync_err_reported = True
 
 
@@ -68,6 +69,8 @@ def __init__(self, mqtt_client: mqttclient.MqttClient, contr: controller.Control
         self.timesync: TimeSyncFlag = timesync
 
         self.last_command_bak = None
+        self.min_after_sunrise = None  # this overrides the local configuration
+        self.min_after_sunset = None   # this overrides the local configuration
 
     def update_status(self):
         systemtime_synced = self.timesync.is_systemtime_synced()
@@ -80,15 +83,15 @@ def notify_force_expired(self):
         self.mqtt_client.publish(config_dict['topic_conf']['force_operation'], {'command': 'auto', 'started_isodt': None})
 
     def report_err(self, code, err_str):
-        print('error {0}: {1}'.format(code, err_str))
+        logging.info('error {0}: {1}'.format(code, err_str))
 
     def clear_err(self):
         pass
 
     def command_changed(self, command_out):
         if command_out != self.last_command_bak:
             self.last_command_bak = deepcopy(command_out)
-            print('Next action is: {0}'.format(command_out))
+            logging.info('Next action is: {0}'.format(command_out))
             self.io.update_commands(command_out)
             self.update_status()
 
@@ -112,31 +115,33 @@ def get_datetime_now(self):
 
     # ---------- incoming event methods ----------
     def on_sun_times_conf(self, topic, content_dict):
-        print('message arrived, topic {0}: {1}'.format(topic, content_dict))
+        logging.info('message arrived, topic {0}: {1}'.format(topic, content_dict))
 
         global config_dict
 
         try:
-            min_after_sunrise = int(content_dict['min_after_sunrise'])
-            min_after_sunset = int(content_dict['min_after_sunset'])
-            door_times, door_times_converted = timecontrol.recalc_door_times(config_dict['time_control'], datetime.date.today(), min_after_sunrise, min_after_sunset)
+            self.min_after_sunrise = int(content_dict['min_after_sunrise'])
+            self.min_after_sunset = int(content_dict['min_after_sunset'])
+            door_times, door_times_converted = timecontrol.recalc_door_times(config_dict['time_control'], datetime.date.today(),
+                                                                             self.min_after_sunrise, self.min_after_sunset)
             self.mqtt_client.publish(config_dict['topic_conf']['sun_times'], door_times_converted)
+            self.controller.set_sunbased_time(door_times_converted['sunrise_open_time'], door_times_converted['sunset_close_time'])
         except KeyError as e:
-            print('Unexpected/missing MQTT content in {0}: {1}'.format(topic, e))
+            logging.warning('Unexpected/missing MQTT content in {0}: {1}'.format(topic, e))
 
     def on_door_prio(self, topic, content_dict):
-        print('message arrived, topic {0}: {1}'.format(topic, content_dict))
+        logging.info('message arrived, topic {0}: {1}'.format(topic, content_dict))
         self.controller.set_door_prio(content_dict['open'], content_dict['close'])
 
     def on_static_time(self, topic, content_dict):
-        print('message arrived, topic {0}: {1}'.format(topic, content_dict))
+        logging.info('message arrived, topic {0}: {1}'.format(topic, content_dict))
         try:
             self.controller.set_static_time(content_dict['open'], content_dict['close'])
         except KeyError as e:
-            print('Unexpected/missing MQTT content in {0}: {1}'.format(topic, e))
+            logging.warning('Unexpected/missing MQTT content in {0}: {1}'.format(topic, e))
 
     def on_force_operation(self, topic, content_dict):
-        print('message arrived, topic {0}: {1}'.format(topic, content_dict))
+        logging.info('message arrived, topic {0}: {1}'.format(topic, content_dict))
         if 'started_isodt' in content_dict:
             self.controller.set_force_operation(content_dict['command'], content_dict['started_isodt'])
         else:
@@ -147,7 +152,12 @@ def on_force_operation(self, topic, content_dict):
 def main():
     parser = argparse.ArgumentParser(description='Door control for chicken - using MQTT for diagnostics')
     parser.add_argument('config_file', help='JSON configuration file', type=argparse.FileType('r'))
+    parser.add_argument('-ll', '--loglevel',
+                        default='info',
+                        help='Set logging level. Example --loglevel debug|info|warning|error, default=info')
+    parser.add_argument('-lf', '--logfile', default=None, help='Logging to a file if set; default: to console')
     args = parser.parse_args()
+    logging.basicConfig(filename=args.logfile, level=args.loglevel.upper())
 
     global config_dict
     config_dict = json.load(args.config_file)
@@ -165,7 +175,7 @@ def main():
     last_calc_date = datetime.date.today()
     door_times, door_times_converted = timecontrol.recalc_door_times(config_dict['time_control'], last_calc_date, None, None)
     contr.set_sunbased_time(door_times_converted['sunrise_open_time'], door_times_converted['sunset_close_time'])
-    print('initially calculated sunrise and sunset time for {0}: {1}'.format(last_calc_date.isoformat(), door_times_converted))
+    logging.info('initially calculated sunrise and sunset time for {0}: {1}'.format(last_calc_date.isoformat(), door_times_converted))
 
     topic_list = [
         (config_dict['topic_conf']['door_sun_times_conf'], dispatcher.on_sun_times_conf),
@@ -182,7 +192,7 @@ def main():
     while True:
         # sleep time but note: MQTT client is listening and always active
         time.sleep(60)
-        print('.')
+        # logging.info('.')
 
         # periodical checks
         # 1. check MQTT connection
@@ -196,33 +206,33 @@ def main():
         # 3. update status LEDs
         dispatcher.update_status()
 
-        # TODO <------- first execute the last command again to not skip the automatic time and directly jump to the next!
+        # 4. first execute pending commands to not skip the automatic time and directly jump to the next!
         io.execute_pending_command()
 
-        # 4. recalc today's sunrise and sunset times
+        # 5. recalc today's sunrise and sunset times
         if timesync.is_systemtime_synced():
             if last_calc_date != datetime.date.today():
                 last_calc_date = datetime.date.today()
                 door_times, door_times_converted = timecontrol.recalc_door_times(config_dict['time_control'],
-                                                                                 last_calc_date, None, None)
+                                                                                 last_calc_date, dispatcher.min_after_sunrise, dispatcher.min_after_sunset)
                 contr.set_sunbased_time(door_times_converted['sunrise_open_time'],
                                         door_times_converted['sunset_close_time'])
-                print('recalculated sunrise and sunset time for {0}: {1}'.format(last_calc_date.isoformat(), door_times_converted))
+                logging.info('recalculated sunrise and sunset time for {0}: {1}'.format(last_calc_date.isoformat(), door_times_converted))
 
-        # 5. recalc open/close state -> this will automatically set the IOs via the dispatcher
+        # 6. recalc open/close state -> this will automatically set the IOs via the dispatcher
         contr.recalc(timesync.is_systemtime_synced())
 
-        # 6. publish last commands
+        # 7. publish last commands
         if last_command_list != io.get_last_command_list():
             last_command_list = io.get_last_command_list()
             mqtt_client.publish(config_dict['topic_conf']['last_commands'], last_command_list)
 
-        # 7. publish last door states (digital input)
+        # 8. publish last door states (digital input)
         if door_closed_log != io.get_door_state_log():
             door_closed_log = io.get_door_state_log()
             mqtt_client.publish(config_dict['topic_conf']['door_closed_log'], door_closed_log)
 
-        # 8. send life sign
+        # 9. send life sign
         mqtt_client.publish_volatile(config_dict['topic_conf']['door_lifesign'], {'last': datetime.datetime.now().isoformat(timespec='seconds')})
 
     mqtt_client.disconnect()

safechicken/mqttclient.py

@@ -3,13 +3,14 @@
 
 import paho.mqtt.client as mqtt
 import time
+import logging
 
 
 def test_connection(mqtt_config):
-    print(mqtt_config)
+    logging.info(mqtt_config)
 
     def on_message(client, userdata, message):
-        print("received message: ", str(message.payload.decode("utf-8")))
+        logging.info("received message: ", str(message.payload.decode("utf-8")))
 
     mqtt_broker = mqtt_config['broker_hostname']
 
@@ -28,7 +29,7 @@ def on_message(client, userdata, message):
 
 
 def _on_mqtt_message(mqtt_client, paho_client, userdata, message):
-    print('received message {0}: {1}'.format(message.topic, str(message.payload.decode("utf-8"))))
+    logging.info('received message {0}: {1}'.format(message.topic, str(message.payload.decode("utf-8"))))
     topic_func = mqtt_client.get_topic_func(message.topic)
     if topic_func:
         topic_func(message.topic, json.loads(message.payload.decode("utf-8")))
@@ -46,14 +47,14 @@ def connect_subscribe(self, topic_list):
             self.client.connect(self.mqtt_config['broker_hostname'])
             self.client.on_message = functools.partial(_on_mqtt_message, self)
             self.client.loop_start()
-            print('MQTT connected to {0}'.format(self.mqtt_config['broker_hostname']))
+            logging.info('MQTT connected to {0}'.format(self.mqtt_config['broker_hostname']))
 
             self.topic_list = topic_list
 
             for topic_elem in topic_list:
                 self.client.subscribe(topic_elem[0])
         except Exception as e:
-            print('Error on MQTT connection (retry later): {0}'.format(e))
+            logging.warning('Error on MQTT connection (retry later): {0}'.format(e))
 
     def disconnect(self):
         self.client.loop_stop()