Critical: Fixed a case where the system fails to allow the user to check out a key.

Minor logging fixes.

Author: aryan-programmer

current_key_store.py

@@ -1,9 +1,11 @@
-import dataclasses
+
 import datetime
+import logging
 from data_objects import KeyData
 from database import KeysDB
 from event import Event
 from key_solenoid_lock import KeySolenoidLock
+from logger_instance import logger
 from mfrc522 import SimpleMFRC522
 
 KEY_STOLEN_LIMIT = datetime.timedelta(seconds=1)
@@ -39,14 +41,6 @@ def __init__(
         self.keys_db = keys_db if keys_db is not None else KeysDB()
 
     def key_tick(self):
-        card_id = self.key_reader.read_id(timeout=self.key_reader_timeout_s)
-        # if card_id is not None:
-        #     print("Past Key: ", past_key_card_id)
-        #     print("Key: ", card_id)
-        if self.past_key_card_id == card_id:
-            self.past_key_card_id = card_id
-            return
-
         if (
             self._is_key_being_stolen
             and datetime.datetime.now() >= self._key_stolen_decision_time
@@ -56,14 +50,22 @@ def key_tick(self):
             self._key_stolen_decision_time = None
             self.key_stolen.trigger()
 
+        card_id = self.key_reader.read_id(timeout=self.key_reader_timeout_s)
+        # if card_id is not None:
+        #     print("Past Key: ", past_key_card_id)
+        #     print("Key: ", card_id)
+        if self.past_key_card_id == card_id:
+            self.past_key_card_id = card_id
+            return
+
         if self.key_locker.is_key_locked:
             if self.past_key_card_id is None:
                 if (
                     self._is_key_being_stolen
                     and datetime.datetime.now() < self._key_stolen_decision_time
                     and self._past_stolen_key_card_id == card_id
                 ):
-                    print("Key re-found")
+                    logger.log(logging.INFO, "Key re-found")
                     self.past_key_card_id = card_id
                     self._is_key_being_stolen = False
                     self._past_stolen_key_card_id = None
@@ -72,7 +74,7 @@ def key_tick(self):
                 else:
                     self.unauthorized_key_swap_attempted.trigger()
             else:
-                print("Key missing")
+                logger.log(logging.INFO, "Key missing")
                 self._is_key_being_stolen = True
                 self._past_stolen_key_card_id = self.past_key_card_id
                 self.past_key_card_id = None
@@ -87,3 +89,6 @@ def key_tick(self):
                 self.key_locker.is_key_locked = True
             else:
                 self.unauthorized_key_swap_attempted.trigger()
+        else:
+            self.past_key_card_id = None
+            self.key_locker.is_key_locked = True

data_objects.py

@@ -1,4 +1,6 @@
+
 from dataclasses import dataclass
+from typing import List
 
 
 @dataclass
@@ -13,4 +15,4 @@ class UserData:
     id: str
     rf_id: str
     name: str
-    authorized_for: [str]
+    authorized_for: List[str]

database.json

@@ -6,6 +6,7 @@
 			"name": "Key 1"
 		}
 		// f37199a6bd
+		// b815fc1243
 	],
 	"users": [
 		{
@@ -17,5 +18,6 @@
 			]
 		}
 		// 53b5249654
+		// 625b46512e
 	]
 }

database.py

@@ -1,3 +1,4 @@
+
 import functools
 from typing import Dict
 
@@ -11,7 +12,8 @@
 def parse_database():
     with open('./database.json') as json_data:
         d = pyjson5.load(json_data)
-        keys = [KeyData(id=v["id"], rf_id=v["rf_id"], name=v["name"]) for v in d["keys"]]
+        keys = [KeyData(id=v["id"], rf_id=v["rf_id"], name=v["name"])
+                for v in d["keys"]]
         users = [UserData(id=v["id"], rf_id=v["rf_id"], name=v["name"], authorized_for=v["authorized_for"]) for v in
                  d["users"]]
         return keys, users

event.py

@@ -1,3 +1,4 @@
+
 class Event:
     def __init__(self):
         # Initialise a list of listeners

key_solenoid_lock.py

@@ -1,4 +1,7 @@
+
 from threading import RLock
+from logger_instance import logger
+import logging
 
 import gpiozero
 
@@ -21,10 +24,10 @@ def is_key_locked(self) -> bool:
     def is_key_locked(self, value: bool):
         with self._lock:
             if value:
-                print("Locking key")
+                logger.log(logging.INFO, "Locking key")
                 self._is_key_locked = True
                 self._solenoid_controller.off()
             else:
-                print("Unlocking key")
+                logger.log(logging.INFO, "Unlocking key")
                 self._is_key_locked = False
                 self._solenoid_controller.on()

logger_instance.py

@@ -0,0 +1,17 @@
+
+import logging
+import logging.handlers
+
+logger = logging.getLogger("mfrc522Logger")
+logFormatter = logging.Formatter(
+    "%(asctime)s [%(threadName)-12.12s] [%(levelname)-8.8s]  %(message)s")
+
+fileHandler = logging.FileHandler("./key_guard.log")
+fileHandler.setFormatter(logFormatter)
+logger.addHandler(fileHandler)
+
+consoleHandler = logging.StreamHandler()
+consoleHandler.setFormatter(logFormatter)
+logger.addHandler(consoleHandler)
+level = logging.getLevelName(logging.INFO)
+logger.setLevel(level)

main.py

@@ -1,10 +1,11 @@
+
 import logging
 import threading
 import time
 
 import gpiozero
 from RPi import GPIO
-from gpiozero.tones import Tone
+# from gpiozero.tones import Tone
 
 from current_key_store import CurrentKeyStore
 from data_objects import UserData, KeyData
@@ -13,6 +14,8 @@
 from mfrc522 import SimpleMFRC522
 from mfrc522.chip_select_lock import ChipSelectLinesLock
 
+from logger_instance import logger
+
 
 def set_pin_mode():
     pin_mode = GPIO.BCM
@@ -26,17 +29,12 @@ def set_pin_mode():
 
 # source ../.virtualenvs/key-guard/bin/activate
 
-logger = logging.getLogger("mfrc522Logger")
-logger.addHandler(logging.StreamHandler())
-level = logging.getLevelName(logging.WARN)
-logger.setLevel(level)
-
 RELOCK_KEY_TIMEOUT_S = 5
 READER_TIMEOUT_S = 0.5
 MAIN_LOOP_DELAY_S = 1 / 1000
 
 led = gpiozero.LED(27)
-buzzer = gpiozero.TonalBuzzer(12, mid_tone=Tone("A5"))
+# buzzer = gpiozero.TonalBuzzer(12, mid_tone=Tone("A5"))
 solenoid_controller = gpiozero.DigitalOutputDevice(23)
 set_pin_mode()
 reset_pin = gpiozero.DigitalOutputDevice(22)
@@ -48,9 +46,12 @@ def set_pin_mode():
 user_reader_select = gpiozero.DigitalOutputDevice(5)
 key_reader_select = gpiozero.DigitalOutputDevice(6)
 lines_locks = ChipSelectLinesLock([user_reader_select, key_reader_select])
-user_reader = SimpleMFRC522(bus=0, device=0, lock=lines_locks.individual_line_lock(0))
-key_reader = SimpleMFRC522(bus=0, device=0, lock=lines_locks.individual_line_lock(1))
-key_locker = KeySolenoidLock(init_locked=False, solenoid_controller=solenoid_controller)
+user_reader = SimpleMFRC522(
+    bus=0, device=0, lock=lines_locks.individual_line_lock(0))
+key_reader = SimpleMFRC522(
+    bus=0, device=0, lock=lines_locks.individual_line_lock(1))
+key_locker = KeySolenoidLock(
+    init_locked=False, solenoid_controller=solenoid_controller)
 past_user_card_id: str | None = None
 current_key_store = CurrentKeyStore(
     key_locker=key_locker,
@@ -59,58 +60,58 @@ def set_pin_mode():
     key_relock_timeout_s=RELOCK_KEY_TIMEOUT_S,
 )
 
-print(
-    f"Buzzer data: min: {buzzer.min_tone.frequency}, mid: {buzzer.mid_tone.frequency}, max: {buzzer.max_tone.frequency}"
-)
+# print(
+#     f"Buzzer data: min: {buzzer.min_tone.frequency}, mid: {buzzer.mid_tone.frequency}, max: {buzzer.max_tone.frequency}"
+# )
 
 
-def turn_off_buzzer():
-    buzzer.stop()
+# def turn_off_buzzer():
+#     buzzer.stop()
 
 
 @current_key_store.unauthorized_key_swap_attempted.on
 def on_unauthorized_key_swap_attempted():
-    print("Unauthorized key swap attempted.")
+    logger.log(logging.WARNING, "Unauthorized key swap attempted.")
     led.blink(0.125, 0.125, 16)
     # buzzer.play(Tone.from_frequency(1300))
     # threading.Timer(3, turn_off_buzzer).start()
 
 
 @current_key_store.key_stolen.on
 def on_key_stolen():
-    print("Key stolen.")
+    logger.log(logging.WARNING, "Key stolen.")
     led.blink(0.125, 0.125, 8)
-    buzzer.play(Tone.from_frequency(1700))
-    threading.Timer(7, turn_off_buzzer).start()
+    # buzzer.play(Tone.from_frequency(1700))
+    # threading.Timer(7, turn_off_buzzer).start()
 
 
 @current_key_store.key_found.on
 def on_key_found(key: KeyData):
-    print("Key found: ", key)
+    logger.log(logging.INFO, "Key found: %s", key)
     led.blink(0.25, 0.25, 4)
-    buzzer.play(Tone.from_frequency(440))
-    threading.Timer(1, turn_off_buzzer).start()
+    # buzzer.play(Tone.from_frequency(440))
+    # threading.Timer(1, turn_off_buzzer).start()
 
 
 def on_user_found(user: UserData):
-    print("User found: ", user)
+    logger.log(logging.WARNING, "User found: %s", user.name)
     led.blink(0.5, 0.5, 2)
-    buzzer.play(Tone.from_frequency(880))
-    threading.Timer(RELOCK_KEY_TIMEOUT_S, turn_off_buzzer).start()
+    # buzzer.play(Tone.from_frequency(880))
+    # threading.Timer(RELOCK_KEY_TIMEOUT_S, turn_off_buzzer).start()
 
 
 def on_unknown_user_found(card_id):
-    print("Unknown user: Card ID: ", card_id)
+    logger.log(logging.WARNING, "Unknown user: Card ID: %s", card_id)
     led.blink(1, 1, 1)
     # buzzer.play(Tone.from_frequency(440))
     # threading.Timer(3, turn_off_buzzer).start()
 
 
 def relock_key_timeout_handler():
-    print("Re-locking key")
+    logger.log(logging.INFO, "Re-locking key")
     current_key_store.key_tick()
     key_locker.is_key_locked = True
-    turn_off_buzzer()
+    # turn_off_buzzer()
 
 
 def user_tick():
@@ -127,7 +128,8 @@ def user_tick():
     if user is not None:
         on_user_found(user)
         key_locker.is_key_locked = False
-        threading.Timer(RELOCK_KEY_TIMEOUT_S, relock_key_timeout_handler).start()
+        threading.Timer(RELOCK_KEY_TIMEOUT_S,
+                        relock_key_timeout_handler).start()
     elif card_id is not None:
         on_unknown_user_found(card_id)
 
@@ -136,7 +138,7 @@ def user_tick():
 
 def on_rfid_card_found(card_id):
     led.blink(0.75, 0.25, 3)
-    print("Unknown card given: ", card_id)
+    logger.log(logging.WARNING, "Unknown card given: %s", card_id)
 
 
 try:
@@ -150,3 +152,4 @@ def on_rfid_card_found(card_id):
     key_reader.cleanup()
     user_reader.cleanup()
     GPIO.cleanup()
+    logging.shutdown()

mfrc522/MFRC522.py

@@ -20,6 +20,7 @@
 #    You should have received a copy of the GNU Lesser General Public License
 #    along with MFRC522-Python.  If not, see <http://www.gnu.org/licenses/>.
 #
+
 import logging
 import traceback
 

mfrc522/SimpleMFRC522.py

@@ -1,3 +1,4 @@
+
 import math
 import time
 

mfrc522/__init__.py

@@ -1,3 +1,4 @@
+
 from .MFRC522 import MFRC522
 from .SimpleMFRC522 import SimpleMFRC522
 

mfrc522/chip_select_lock.py

@@ -1,3 +1,4 @@
+
 from dataclasses import dataclass
 from threading import RLock
 from typing import List

singleton.py

@@ -1,3 +1,4 @@
+
 class _Singleton(type):
     """ A metaclass that creates a Singleton base class when called. """
     _instances = {}

utils.py

@@ -1,6 +1,8 @@
 from contextlib import contextmanager
 from functools import wraps
 from time import perf_counter
+from logger_instance import logger
+import logging
 
 
 def timing_decorator(f):
@@ -9,7 +11,8 @@ def wrap(*args, **kw):
         ts = perf_counter()
         result = f(*args, **kw)
         te = perf_counter()
-        print(f'func:{f.__name__!r} args:[{args!r}, {kw!r}] took: {te - ts:2.4f} sec')
+        logger.log(
+            logging.INFO, f'func:{f.__name__!r} args:[{args!r}, {kw!r}] took: {te - ts:2.4f} sec')
         return result
 
     return wrap
@@ -27,4 +30,4 @@ def timing_wither(name) -> float:
     t1 = t2 = perf_counter()
     yield
     t2 = perf_counter()
-    print(f'func:{name} took: {t2 - t1:2.4f} sec')
+    logger.log(logging.INFO, f'func:{name} took: {t2 - t1:2.4f} sec')