diff --git a/door.py b/door.py index b3f6204..cf10716 100644 --- a/door.py +++ b/door.py @@ -1,11 +1,16 @@ #!/usr/bin/python -import os, serial, socket, subprocess, select, datetime, sys +import os, serial, socket, select, datetime import paho.mqtt.client as mqcl import argparse +import logging -OPEN_THRESHOLD = 35 -CLOSED_THRESHOLD = 60 -CLOSED_WANT = 135 +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") @@ -14,344 +19,407 @@ 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() -mqttc = mqcl.Client() - def timestamp(): return datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S") -# Log data to stdout and the log file -def log(*args): - data = "%s %s" % (timestamp(), " ".join(str(i) for i in args)) - lgf.write(data + "\n") - lgf.flush() - print(data) - -def mqtt(topic, msg, persistent = True): - mqttc.publish("door/" + topic, msg, qos=2, retain=persistent) - -# Opens the socket that can control the daemon -# Commands are TBD -def open_control_socket(): - global control_socket - global config - global comm_channels - - 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 = [] - -# Opens the serial port to talk to the lock actuator -# Might return a failure. In that case, it will be tried again later -def open_serial_port(): - global serial_port - global config - - try: - serial_port = serial.Serial(config.serial_port, timeout=2) - except: - serial_port = None - pass - -# Detected tokens are passed in through a FIFO -def open_nfc_fifo(): - global nfc_fifo - global config - - nfc_fifo = open(config.nfc_fifo, "r") - -# Refresh valid tokens from the configured file -def read_valid_tokens(): - global valid - global config - - try: - log("Loading tokens") - valid = {} - 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: - log(f"Could not parse valid thru date for token {token} in line {i}") - valid_thru = None - log(f"Got token {token} associated with {name} <{email}> of {organization}, valid thru {valid_thru}") - if token in valid: - log(f"Warning: Overwriting token {token}") - valid[token] = {'name': name, 'organization': organization, 'email': email, - 'valid_thru': valid_thru} - else: - log(f"Skipping line {i} ({line}) since it does not contain exactly 5 data field") - except: - valid = {} - log("Error reading token file") - raise - -# Opens the log file for writing -def open_logfile(): - global lgf - global config - - lgf = open(config.log_file, "a+") - -# Actions -IDLE, CLOSE, OPEN_THEN_CLOSE, OPEN, CLOSE_THEN_OPEN = range(5) -state_names = { - OPEN: "open", - CLOSE: "close" -} -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" -} -# Current door state -state = None -state_pos = 0 -# Current target action -action = CLOSE -# Start time of the current action -start_time = None -# How often the action was repeated -repeats = 0 - -# Read the state of the door from the serial port -def poll_door_state(): - global state - global state_pos - global serial_port - serial_port.reset_input_buffer() - serial_port.write(b"R") - data = serial_port.readline().strip().split() - if data[0] == b'pos:': - data = int(data[1]) - if state_pos != data: - mqtt("position/value", data, True) - state_pos = data - changed = False - if data < OPEN_THRESHOLD and state != OPEN: - state = OPEN - changed = True - mqtt("state/value", "open", True) - elif data > CLOSED_THRESHOLD and state != CLOSE: - state = CLOSE - changed = True - mqtt("state/value", "closed", True) - return state - -# Check the door state and send commands through a state machine -def handle_door_state(): - global action, target, serial_port, start_time, repeats - - # Commands associated with each target state - target_state_cmd = { - OPEN: b'O', - CLOSE: b'C' - } - - old_state = state - - # If no serial port, try to open it or return - if not serial_port: - try: - open_serial_port() - except: - return - - # Get new state - poll_door_state() - - # Idle + change = key? - if action == IDLE: - if state != old_state: - log("Door changed unexpectedly:", state_names[state]) - start_time = datetime.datetime.now() - if start_time and (datetime.datetime.now() - start_time).total_seconds() >= config.state_timeout: - start_time = None - if state_pos >= CLOSED_THRESHOLD and state_pos < CLOSED_WANT: - log("Closing door a bit more") - serial_port.write(target_state_cmd[CLOSE]) - return - - # Target state, next action, timeout action - actions = { - OPEN: (OPEN, IDLE, CLOSE_THEN_OPEN ), - CLOSE: (CLOSE, IDLE, OPEN_THEN_CLOSE ), - OPEN_THEN_CLOSE: (OPEN, CLOSE, CLOSE ), - CLOSE_THEN_OPEN: (CLOSE, OPEN, OPEN ) +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", } - if start_time == None: - start_time = datetime.datetime.now() - serial_port.write(target_state_cmd[actions[action][0]]) + def __init__(self, config): + self.config = config - # Target state reached - if state == actions[action][0]: - # Select next action, reset start time and repetitions - action = actions[action][1] - start_time = datetime.datetime.now() - repeats = 0 - # On idle, we're done - if action == IDLE: - log("Reached target position:", state_names[state]) + 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 = None + self.state_pos = 0 + # Current target action + self.action = DoorControl.CLOSE + # 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 mqtt(self, topic: str, msg: str, persistent: bool = True): + """Publishes data to a topic""" + self.mqttc.publish("door/" + topic, msg, qos=2, retain=persistent) + + 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: + 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""" + if self.state_pos != data: + self.mqtt("position/value", data, True) + 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.mqtt("state/value", "open", True) + self.state = DoorControl.OPEN + elif data < CLOSED_THRESHOLD and self.state != DoorControl.CLOSE: + self.mqtt("state/value", "closed", True) + 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 - # Execution time - t = (datetime.datetime.now() - start_time).total_seconds() - if t >= config.state_timeout: - # Timeout -> switch to timeout action - action = actions[action][2] - start_time = None - repeats = 0 - log("Timeout. Switching to", action_names[action]) - elif t >= (1 + repeats) * config.repeat_time: - # Repeat every couple of seconds - repeats += 1 - serial_port.write(target_state_cmd[actions[action][0]]) - log("Repeating command:", target_state_cmd[actions[action][0]]) + speed = abs(self.state_pos - self.last_position) / delta_t + self.last_position = self.state_pos + self.last_handle_state_timestamp = now + + if speed >= 0 or delta_t >= 1. / UPDATE_RATE: + self.mqtt("position/speed", f"{speed}") -def open_door(): - global action - global start_time - log("Opening the door") - action = OPEN - start_time = None - mqtt("state/target", "open", True) - handle_door_state() + # If no serial port, try to open it or return + if not self.serial_port: + try: + self._open_serial_port(self.config) + except: + return -def close_door(): - global action - global start_time - log("Closing the door") - action = CLOSE - start_time = None - mqtt("state/target", "closed", True) - handle_door_state() + # Get new state + self.poll_door_state() + self.last_handled_state = self.state -def toggle_door_state(): - global state, action - if state == CLOSE: - open_door() - else: - close_door() + if self.state == DoorControl.ERROR: + self.logger.error("Restarting the MCU and exiting.") + self.send_door_cmd(b'S') + return -def handle_nfc_token(token = None): - global valid - - if not token: - token = nfc_fifo.readline() - if token == "": - open_nfc_fifo() + # 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 - token = token.strip() - if token in valid: - data = valid[token] + # 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 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'] + 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 speed < MIN_SPEED and delta_t >= 1. / UPDATE_RATE): + # Timeout -> switch to timeout action + self.state = actions[self.action][0] + 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.mqtt("state/target", "open", True) + self.action = DoorControl.OPEN + self.start_time = None + self.handle_door_state() + + def close_door(self): + self.logger.info("Closing the door") + self.mqtt("state/target", "closed", True) + self.action = DoorControl.CLOSE + self.start_time = None + self.handle_door_state() + + def toggle_door_state(self): + if self.state == DoorControl.CLOSE: + self.open_door() else: - # otherwise we don't need to check - authorized = True + self.close_door() - if authorized: - log(f"Valid token {token} of {data['name']}") - toggle_door_state() + 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: - log(f"Token {token} of {data['name']} expired on {data['valid_thru']}") - else: - log("Invalid token:", token) - mqtt("token/last_invalid", "%s;%s" % (timestamp(), token)) + self.logger.warning(f"Invalid token: {token}") + self.mqtt("token/last_invalid", "%s;%s" % (timestamp(), token)) -class LineBuffer(object): - def __init__(self, f, handler): - self.data = b'' - self.f = f - self.handler = handler + 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 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(comm, data): - cmd = data.decode('utf8').split() - cmd, args = cmd[0], cmd[1:] - log("Got command:", data) + 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')) + send = lambda x: comm.send(x.encode('utf8')) - if cmd == 'fake': - log("Faking token", args[0]) - send("Handling token\n") - handle_nfc_token(args[0]) - elif cmd == 'open': - log("Control socket opening door") - send("Opening door") - open_door() - elif cmd == 'close': - log("Control socket closing door") - send("Closing door") - close_door() - elif cmd == 'rld': - log("Reloading tokens") - send("Reloading tokens") - read_valid_tokens() - elif cmd == 'stat': - send("Door status is %s, position is %d. Current action: %s (%g seconds ago)\n" % ( - state_names.get(state, "None"), - state_pos, - action_names[action], - (datetime.datetime.now() - start_time).total_seconds())) + 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, + DoorControl.action_names[self.action], + (datetime.datetime.now() - self.start_time).total_seconds())) -open_logfile() -read_valid_tokens() -open_nfc_fifo() -open_serial_port() -open_control_socket() -mqttc.on_connect = lambda client, userdata, flags, rc: log("Connected to mqtt host with result %s" % (str(rc), )) -mqttc.connect_async(config.mqtt_host, keepalive = 60) -mqttc.loop_start() +dc = DoorControl(config) buffers = {} while True: - readable = select.select([ nfc_fifo, control_socket ] + comm_channels, [], [], 1)[0] + 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 == nfc_fifo: - handle_nfc_token() - elif c == control_socket: - log("Got connection") - sock = control_socket.accept()[0] - buffers[sock] = LineBuffer(sock, handle_cmd) - comm_channels += [sock] + 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(): - log("Lost connection") + dc.logger.info("Lost connection") del buffers[c] - comm_channels.remove(c) - handle_door_state() + dc.comm_channels.remove(c) + dc.handle_door_state()