DoorControl/door.py

#!/usr/bin/python
import os, serial, socket, select, datetime
import paho.mqtt.client as mqcl
import argparse
import logging

UPDATE_RATE = 2
MAX_UPDATE_RATE = 20
MIN_SPEED = 5
ERROR_THRESHOLD = 250
OPEN_THRESHOLD = 190
CLOSED_THRESHOLD = 160
CLOSED_WANT = 40

parser = argparse.ArgumentParser()
parser.add_argument("--serial_port", default="/dev/serial/by-id/usb-Imaginaerraum.de_DoorControl_43363220195053573A002C0-if01")
parser.add_argument("--nfc_fifo", default="/tmp/nfc_fifo")
parser.add_argument("--control_socket", default="/tmp/nfc.sock")
parser.add_argument("--valid_tokens", default="/etc/door_tokens")
parser.add_argument("--log_file", default="/tmp/nfc.log")
parser.add_argument("--state_timeout", type=float, default=10)
parser.add_argument("--state_timeout_speed", type=float, default=3)
parser.add_argument("--repeat_time", type=float, default=5)
parser.add_argument("--mqtt_host", default="10.10.21.2")

config = parser.parse_args()

def timestamp():
    return datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")

class MqttValue:
    def __init__(self, client, topic, persistent = False, start_value = None, *, translate = None, max_update = 0.1):
        self.client = client
        self.topic = topic
        self.persistent = persistent
        self.value = start_value
        self.last_update = datetime.datetime.now() - datetime.timedelta(seconds = max_update)
        self.last_update_value = None
        self.max_update = max_update

        if translate == None:
            self.translate = str
        elif callable(translate):
            self.translate = translate
        else:
            self.translate = lambda x: translate[x]
        
        if start_value != None:
            self.update(start_value)

    def update(self, value, force = False, no_update = False):
        if value != self.value or value != self.last_update_value:
            self.value = value
            if force or (not no_update and value != self.last_update_value and (datetime.datetime.now() - self.last_update).total_seconds() >= self.max_update):
                self.last_update = datetime.datetime.now()
                self.last_update_value = value
                self.client.publish(self.topic, self.translate(value), qos = 2, retain = self.persistent)

    def force_update(self, value):
        self.update(value, force = True)

    def __call__(self, value = None, **kwargs):
        if value != None:
            self.update(value, **kwargs)
        else:
            return self.value

class DoorControl:
    # Actions
    IDLE, CLOSE, OPEN_THEN_CLOSE, OPEN, CLOSE_THEN_OPEN, ERROR = range(6)
    state_names = {
        OPEN: "open",
        CLOSE: "close",
        ERROR: "error",
    }
    action_names = {
        IDLE: "idling",
        OPEN: "waiting for open door",
        CLOSE: "waiting for closed door",
        OPEN_THEN_CLOSE: "waiting for open door, then closing again",
        CLOSE_THEN_OPEN: "waiting for closed door, then opening again",
        ERROR: "error",
    }

    def __init__(self, config):
        self.config = config

        self.mqttc = mqcl.Client()
        self.logger = self._setup_logging(config)
        self._open_serial_port(config)
        self.valid_tokens = self._read_valid_tokens(config)
        self.nfc_fifo = self._open_nfc_fifo(config)
        self.control_socket, self.comm_channels = self._open_control_socket(config)

        self.mqttc.on_connect = lambda client, userdata, flags, rc: self.logger.info(f"Connected to mqtt host with result {rc}")
        self.mqttc.connect_async(config.mqtt_host, keepalive=60)
        self.mqttc.loop_start()

        # Current door state
        self.state = MqttValue(self.mqttc, "door/state/value", True, translate = self.state_names)
        self.state_target = MqttValue(self.mqttc, "door/state/target", True, translate = self.state_names, max_update = 0)
        self.state_pos = MqttValue(self.mqttc, "door/position/value", True, 0)
        self.last_invalid_token = MqttValue(self.mqttc, "door/token/last_invalid", True)
        self.speed = MqttValue(self.mqttc, "door/position/speed")
        # Current target action
        self.action = MqttValue(self.mqttc, "door/state/action", True, DoorControl.CLOSE, translate = self.action_names, max_update = 0)
        # Start time of the current action
        self.start_time = None
        # How often the action was repeated
        self.repeats = 0

        self.last_handled_state = self.OPEN
        self.last_door_pos_time = datetime.datetime.now() - datetime.timedelta(minutes = 10)
        self.last_position = 0
        self.last_handle_state_timestamp = datetime.datetime.now()

    def _send_door_cmd(self, cmd: bytes):
        """Send a command to the door."""
        if cmd != b'R': self.logger.debug(f"Sending {cmd}")
        return self.serial_port.write(cmd)

    def _read_door_line(self):
        """Read a single line from the serial port"""
        return self.serial_port.readline().decode('ascii')

    def _setup_logging(self, config):
        """Set up logging"""
        log_format = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
        logging.basicConfig(force = True,
                            level = logging.DEBUG,
                            format = log_format)

        # create logger
        logger = logging.getLogger('nfc_log')

        # create console handler and set level to debug
        fh = logging.FileHandler(config.log_file)
        fh.setLevel(logging.DEBUG)

        # create formatter
        formatter = logging.Formatter(log_format)
        fh.setFormatter(formatter)
        logger.addHandler(fh)

        return logger

    def _open_control_socket(self, config):
        """(Re-)creates and opens the control socket. Config must have a control_socket member."""
        self.logger.debug("Opening control socket")
        if os.path.exists(config.control_socket):
            os.unlink(config.control_socket)

        control_socket = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
        control_socket.bind(config.control_socket)
        control_socket.listen(5)
        comm_channels = []

        return control_socket, comm_channels

    def _open_serial_port(self, config):
        """Opens the serial port controlling the door opener. config must have a serial_port member."""
        try:
            self.serial_port = serial.Serial(config.serial_port, timeout=2)
            self._send_door_cmd(b'r')
        except:
            self.serial_port = None
        return self.serial_port

    def _open_nfc_fifo(self, config):
        """Opens config.nfc_fifo as the FIFO through which detected tokens are passed in."""
        nfc_fifo = open(config.nfc_fifo, "r")
        return nfc_fifo

    def _read_valid_tokens(self, config):
        """Refreshes all tokens from config.valid_tokens"""
        valid = {}
        try:
            self.logger.info("Loading tokens")
            lines =[ s.strip() for s in open(config.valid_tokens, "r").readlines() ]
            for i, line in enumerate(lines):
                l = line.split('|')
                if len(l) == 5:
                    if not l[0].strip().startswith('#'):
                        token, name, organization, email, valid_thru = l
                        try:
                            if len(valid_thru.strip()) > 0:
                                valid_thru = datetime.date.fromisoformat(valid_thru)
                            else:
                                valid_thru = None
                        except Exception:
                            logging.error(f"Could not parse valid thru date for token {token} in line {i}")
                            valid_thru = None
                        logging.debug(f"Got token {token} associated with {name} <{email}> of {organization}, valid thru {valid_thru}")
                        if token in valid:
                            logging.warning(f"Overwriting token {token}")
                        valid[token] = {'name': name, 'organization': organization, 'email': email,
                                        'valid_thru': valid_thru}
                else:
                    logging.warning(f"Skipping line {i} ({line}) since it does not contain exactly 5 data field")
        except Exception as e:
            valid = {}
            logging.error(f"Error reading token file. Exception: {e}")

        return valid

    def _set_position(self, data: int):
        """Set a new door position"""
        self.state_pos(data)
        if data > ERROR_THRESHOLD and self.state() != DoorControl.ERROR:
            self.logger.error("Invalid position:", state)
            self.state(DoorControl.ERROR)
        elif data > OPEN_THRESHOLD and self.state() != DoorControl.OPEN:
            self.state(DoorControl.OPEN)
        elif data < CLOSED_THRESHOLD and self.state() != DoorControl.CLOSE:
            self.state(DoorControl.CLOSE)

    def _check_reporting(self, current: int):
        if current == 0:
            self.logger.info("Turning position reporting on")
            self._send_door_cmd(b'r')
        else:
            self.logger.info("Position reporting is on")

    def handle_door_line(self):
        """Reads a single line from the serial port and handles it"""
        data = self._read_door_line().strip()

        handling = {
            "pos": (int, self._set_position),
            "pos reporting": (int, self._check_reporting),
        }

        try:
            prefix, data = data.split(':')
            if prefix in handling:
                data_type, fun = handling[prefix]
                fun(data_type(data))
        except:
            pass

    def poll_door_state(self):
        """Checks the door state if the last polling was at least 5 seconds ago, and returns the current state"""
        t = (datetime.datetime.now() - self.last_door_pos_time).total_seconds()
        if t >= 5:
            self.last_door_pos_time = datetime.datetime.now()
            self._send_door_cmd(b"R")
            self.handle_door_line()
        return self.state()

    def handle_door_state(self):
        """Checks the door state and executes any actions necessary to reach the target state"""
        # Commands associated with each target state
        target_state_cmd = {
            DoorControl.OPEN:  b'O',
            DoorControl.CLOSE: b'C'
        }

        now = datetime.datetime.now()

        old_state = self.last_handled_state
        delta_t = (now - self.last_handle_state_timestamp).total_seconds()

        if 1. / delta_t > MAX_UPDATE_RATE:
            return

        # If no serial port, try to open it or return
        if not self.serial_port:
            try:
                self._open_serial_port(self.config)
            except:
                return

        # Get new state
        self.poll_door_state()
        self.last_handled_state = self.state()
       
        speed = abs(self.state_pos() - self.last_position) / delta_t
        speed = 10 * round(speed / 10)
        self.speed(speed)
        self.last_position = self.state_pos()
        self.last_handle_state_timestamp = now

        if self.state() == DoorControl.ERROR:
            self.logger.error("Restarting the MCU and exiting.")
            self.send_door_cmd(b'S')
            return

        # Idle + change = key?
        if self.action() == DoorControl.IDLE:
            if self.state() != old_state:
                self.logger.info(f"Door changed unexpectedly: {DoorControl.state_names[self.state()]}")
                self.start_time = now
            if self.start_time and (now - self.start_time).total_seconds() >= self.config.state_timeout:
                self.start_time = None
                if self.state_pos() <= CLOSED_THRESHOLD and self.state_pos() > CLOSED_WANT:
                    self.logger.info("Closing door a bit more")
                    self._send_door_cmd(target_state_cmd[DoorControl.CLOSE])
            return

        # Target state, next action, timeout action
        actions = {
            DoorControl.OPEN:  (DoorControl.OPEN,  DoorControl.IDLE, DoorControl.CLOSE_THEN_OPEN ),
            DoorControl.CLOSE: (DoorControl.CLOSE, DoorControl.IDLE, DoorControl.OPEN_THEN_CLOSE ),
            DoorControl.OPEN_THEN_CLOSE: (DoorControl.OPEN, DoorControl.CLOSE, DoorControl.CLOSE ),
            DoorControl.CLOSE_THEN_OPEN: (DoorControl.CLOSE, DoorControl.OPEN, DoorControl.OPEN  )
        }

        if self.start_time is None:
            self.start_time = now
            self._send_door_cmd(target_state_cmd[actions[self.action()][0]])

        # Target state reached
        if self.state() == actions[self.action()][0]:
            # Select next action, reset start time and repetitions
            self.action(actions[self.action()][1])
            self.start_time = now
            self.repeats = 0
            # On idle, we're done
            if self.action() == DoorControl.IDLE:
                self.logger.debug(f"Reached target position: {DoorControl.state_names[self.state()]}")
                return

        # Execution time
        t = (now - self.start_time).total_seconds()
        if t >= self.config.state_timeout or (t >= self.config.state_timeout_speed and self.speed() < MIN_SPEED and delta_t >= 1. / UPDATE_RATE):
            # Timeout -> switch to timeout action
            self.state(actions[self.action()][0], force = True, no_update = True)
            self.action(actions[self.action()][2])
            self.start_time = None
            self.repeats = 0
            self.logger.debug(f"Timeout. Switching to {DoorControl.action_names[self.action()]}")
        elif t >= (1 + self.repeats) * self.config.repeat_time:
            # Repeat every couple of seconds
            self.repeats += 1
            self.logger.debug(f"Repeating command: {target_state_cmd[actions[self.action()][0]]}")
            self._send_door_cmd(target_state_cmd[actions[self.action()][0]])

    def open_door(self):
        self.logger.info("Opening the door")
        self.state_target(DoorControl.OPEN)
        self.action(DoorControl.OPEN)
        self.start_time = None
        self.handle_door_state()

    def close_door(self):
        self.logger.info("Closing the door")
        self.state_target(DoorControl.CLOSE)
        self.action(DoorControl.CLOSE)
        self.start_time = None
        self.handle_door_state()

    def toggle_door_state(self):
        if not self.action() == DoorControl.IDLE:
            return
        if self.state_target() == DoorControl.CLOSE:
            self.open_door()
        else:
            self.close_door()

    def handle_nfc_token(self, token = None):
        if not token:
            token = self.nfc_fifo.readline().strip()
            self.logger.debug(f"Token from nfc_fifo: {token}")
            if token == "":
                self.logger.debug("Opening nfc_fifo")
                self.nfc_fifo = self._open_nfc_fifo(self.config)
                return

        token = token.strip()
        if token in self.valid_tokens:
            data = self.valid_tokens[token]

            if data['valid_thru'] is not None:
                # if a valid thru date has been set we check if the token is still valid
                authorized = datetime.date.today() <= data['valid_thru']
            else:
                # otherwise we don't need to check
                authorized = True

            if authorized:
                self.logger.info(f"Valid token {token} of {data['name']}")
                self.toggle_door_state()
            else:
                self.logger.warning(f"Token {token} of {data['name']} expired on {data['valid_thru']}")
        else:
            self.logger.warning(f"Invalid token: {token}")
            self.last_invalid_token(f"{timestamp()};{token}")

    class LineBuffer(object):
        def __init__(self, f, handler):
            self.data = b''
            self.f = f
            self.handler = handler

        def update(self):
            data = self.f.recv(1024)
            if not data:
                return False
            self.data += data
            d = self.data.split(b'\n')
            d, self.data = d[:-1], d[-1]
            for i in d:
                self.handler(self.f, i)
            return True

    def handle_cmd(self, comm, data):
        cmd = data.decode('utf8').split()
        cmd, args = cmd[0], cmd[1:]
        self.logger.debug(f"Got command: {data}")

        send = lambda x: comm.send(x.encode('utf8'))

        if cmd == 'fake':
            self.logger.debug(f"Faking token {args[0]}")
            send("Handling token\n")
            self.handle_nfc_token(args[0])
        elif cmd == 'open':
            self.logger.debug("Control socket opening door")
            send("Opening door")
            self.open_door()
        elif cmd == 'close':
            self.logger.debug("Control socket closing door")
            send("Closing door")
            self.close_door()
        elif cmd == 'rld':
            self.logger.debug("Reloading tokens")
            send("Reloading tokens")
            self.valid_tokens = self._read_valid_tokens(self.config)
        elif cmd == 'stat':
            send("Door status is %s, position is %d. Current action: %s (%g seconds ago)\n" % (
                DoorControl.state_names.get(self.state, "None"),
                self.state_pos.value,
                DoorControl.action_names[self.action()],
                (datetime.datetime.now() - self.start_time).total_seconds()))


dc = DoorControl(config)

buffers = {}
while True:
    readable = select.select([ dc.serial_port.fileno(), dc.nfc_fifo, dc.control_socket ] + dc.comm_channels, [], [], 1 / UPDATE_RATE)[0]

    for c in readable:
        if c == dc.serial_port.fileno():
            dc.handle_door_line()
        elif c == dc.nfc_fifo:
            dc.handle_nfc_token()
        elif c == dc.control_socket:
            dc.logger.info("Got connection")
            sock = dc.control_socket.accept()[0]
            buffers[sock] = dc.LineBuffer(sock, dc.handle_cmd)
            dc.comm_channels += [sock]
        else:
            if not buffers[c].update():
                dc.logger.info("Lost connection")
                del buffers[c]
                dc.comm_channels.remove(c)
    dc.handle_door_state()