Merge pull request #558 from dbast/logging

Setup Python logging + convert print statements to logger calls

pyproject.toml

@@ -58,6 +58,7 @@ branch = true
 
 [tool.pytest.ini_options]
 testpaths = ["tests"]
+addopts = "-p no:logging"
 
 [tool.setuptools]
 include-package-data = true

src/main.py

@@ -1,4 +1,53 @@
+#!/usr/bin/env python
+
+import argparse
+import logging
+import sys
+
 from seedsigner.controller import Controller
 
-# Get the one and only Controller instance and start our main loop
-Controller.get_instance().start()
+logger = logging.getLogger(__name__)
+
+DEFAULT_MODULE_LOG_LEVELS = {
+    "PIL": logging.WARNING,
+    # "seedsigner.gui.toast": logging.DEBUG,  # example of more specific submodule logging config
+}
+
+
+def main(sys_argv=None):
+    parser = argparse.ArgumentParser()
+    parser.add_argument(
+        "-l",
+        "--loglevel",
+        choices=list((logging._nameToLevel.keys())),
+        default="INFO",
+        type=str,
+        help=(
+            "Set the log level (default: %(default)s), WARNING: changing the log level "
+            "to something more verbose than %(default)s may result in unwanted data "
+            "being written to stderr"
+        ),
+    )
+
+    args = parser.parse_args(sys_argv)
+
+    root_logger = logging.getLogger()
+    root_logger.setLevel(logging.getLevelName(args.loglevel))
+    console_handler = logging.StreamHandler(sys.stderr)
+    console_handler.setFormatter(
+        logging.Formatter("%(asctime)s %(levelname)8s [%(name)s %(funcName)s (%(lineno)d)]: %(message)s")
+    )
+    root_logger.addHandler(console_handler)
+
+    # Set log levels for specific modules
+    for module, level in DEFAULT_MODULE_LOG_LEVELS.items():
+        logging.getLogger(module).setLevel(level)
+
+    logger.info(f"Starting SeedSigner with: {args.__dict__}")
+
+    # Get the one and only Controller instance and start our main loop
+    Controller.get_instance().start()
+
+
+if __name__ == "__main__":
+    main(sys.argv[1:])

src/seedsigner/controller.py

@@ -264,7 +264,7 @@ def start(self, initial_destination: Destination = None) -> None:
             Example:
                 class MyView(View)
                     def run(self, some_arg, other_arg):
-                        print(other_arg)
+                        logger.info(other_arg)
 
                 class OtherView(View):
                     def run(self):
@@ -305,11 +305,11 @@ def run(self):
                     self.psbt_parser = None
                     self.psbt_seed = None
 
-                print(f"back_stack: {self.back_stack}")
+                logger.info(f"\nback_stack: {self.back_stack}")
 
                 try:
                     # Instantiate the View class and run it
-                    print(f"Executing {next_destination}")
+                    logger.info(f"Executing {next_destination}")
                     next_destination = next_destination.run()
 
                 except StopFlowBasedTest:
@@ -337,7 +337,7 @@ def run(self):
                     # Remove the current View from history; it's forwarding us straight
                     # to the next View so it should be as if this View never happened.
                     current_view = self.back_stack.pop()
-                    print(f"Skipping current view: {current_view}")
+                    logger.info(f"Skipping current view: {current_view}")
 
                 # Hang on to this reference...
                 clear_history = next_destination.clear_history
@@ -355,12 +355,10 @@ def run(self):
                 # Do not push a "new" destination if it is the same as the current one on
                 # the top of the stack.
                 if len(self.back_stack) == 0 or self.back_stack[-1] != next_destination:
-                    print(f"Appending next destination: {next_destination}")
+                    logger.info(f"Appending next destination: {next_destination}")
                     self.back_stack.append(next_destination)
                 else:
-                    print(f"NOT appending {next_destination}")
-
-                print("-" * 30)
+                    logger.info(f"NOT appending {next_destination}")
 
         finally:
             from seedsigner.gui.renderer import Renderer
@@ -371,7 +369,7 @@ def run(self):
                 self.toast_notification_thread.stop()
 
             # Clear the screen when exiting
-            print("Clearing screen, exiting")
+            logger.info("Clearing screen, exiting")
             Renderer.get_instance().display_blank_screen()
 
 
@@ -385,10 +383,10 @@ def start_screensaver(self):
         # block until the screensaver is done, at which point the toast can re-acquire
         # the Renderer.lock and resume where it left off.
         if self.toast_notification_thread and self.toast_notification_thread.is_alive():
-            print(f"Controller: settings toggle_render_lock for {self.toast_notification_thread.__class__.__name__}")
+            logger.info(f"Controller: settings toggle_render_lock for {self.toast_notification_thread.__class__.__name__}")
             self.toast_notification_thread.toggle_renderer_lock()
 
-        print("Controller: Starting screensaver")
+        logger.info("Controller: Starting screensaver")
         if not self.screensaver:
             # Do a lazy/late import and instantiation to reduce Controller initial startup time
             from seedsigner.views.screensaver import ScreensaverScreen
@@ -397,7 +395,7 @@ def start_screensaver(self):
 
         # Start the screensaver, but it will block until it can acquire the Renderer.lock.
         self.screensaver.start()
-        print("Controller: Screensaver started")
+        logger.info("Controller: Screensaver started")
 
 
     def reset_screensaver_timeout(self):
@@ -416,16 +414,16 @@ def activate_toast(self, toast_manager_thread: BaseToastOverlayManagerThread):
         """
         if self.is_screensaver_running:
             # New toast notifications break out of the Screensaver
-            print("Controller: stopping screensaver")
+            logger.info("Controller: stopping screensaver")
             self.screensaver.stop()
 
         if self.toast_notification_thread and self.toast_notification_thread.is_alive():
             # Can only run one toast at a time
-            print(f"Controller: stopping {self.toast_notification_thread.__class__.__name__}")
+            logger.info(f"Controller: stopping {self.toast_notification_thread.__class__.__name__}")
             self.toast_notification_thread.stop()
 
         self.toast_notification_thread = toast_manager_thread
-        print(f"Controller: starting {self.toast_notification_thread.__class__.__name__}")
+        logger.info(f"Controller: starting {self.toast_notification_thread.__class__.__name__}")
         self.toast_notification_thread.start()
 
 

src/seedsigner/gui/components.py

@@ -1,3 +1,4 @@
+import logging
 import math
 import os
 import pathlib
@@ -13,6 +14,8 @@
 from seedsigner.models.settings_definition import SettingsConstants
 from seedsigner.models.singleton import Singleton
 
+logger = logging.getLogger(__name__)
+
 
 # TODO: Remove all pixel hard coding
 class GUIConstants:
@@ -1439,7 +1442,7 @@ def reflow_text_into_pages(text: str,
     lines = []
     for line_dict in reflowed_lines_dicts:
         lines.append(line_dict["text"])
-        print(f"""{line_dict["text_width"]:3}: {line_dict["text"]}""")
+        logging.info(f"""{line_dict["text_width"]:3}: {line_dict["text"]}""")
 
     font = Fonts.get_font(font_name=font_name, size=font_size)
     # Measure the font's height above baseline and how for below it certain characters

src/seedsigner/gui/screens/seed_screens.py

@@ -1,4 +1,5 @@
 import math
+import logging
 import time
 
 from dataclasses import dataclass
@@ -16,6 +17,7 @@
 from seedsigner.gui.keyboard import Keyboard, TextEntryDisplay
 from seedsigner.hardware.buttons import HardwareButtons, HardwareButtonsConstants
 
+logger = logging.getLogger(__name__)
 
 
 @dataclass
@@ -1412,9 +1414,9 @@ def __post_init__(self):
 
     def _run_callback(self):
         # Exit the screen on success via a non-None value
-        print(f"verified_index: {self.verified_index.cur_count}")
+        logger.info(f"verified_index: {self.verified_index.cur_count}")
         if self.verified_index.cur_count is not None:
-            print("Screen callback returning success!")
+            logger.info("Screen callback returning success!")
             self.threads[-1].stop()
             while self.threads[-1].is_alive():
                 time.sleep(0.01)

src/seedsigner/gui/toast.py

@@ -1,8 +1,10 @@
+import logging
 import time
 from dataclasses import dataclass
 from seedsigner.gui.components import BaseComponent, GUIConstants, Icon, SeedSignerIconConstants, TextArea
 from seedsigner.models.threads import BaseThread
 
+logger = logging.getLogger(__name__)
 
 
 @dataclass
@@ -119,33 +121,33 @@ def toggle_renderer_lock(self):
 
 
     def run(self):
-        print(f"{self.__class__.__name__}: started")
+        logger.info(f"{self.__class__.__name__}: started")
         start = time.time()
         while time.time() - start < self.activation_delay:
             if self.hw_inputs.has_any_input():
                 # User has pressed a button, cancel the toast
-                print(f"{self.__class__.__name__}: Canceling toast due to user input")
+                logger.info(f"{self.__class__.__name__}: Canceling toast due to user input")
                 return
             time.sleep(0.1)
 
         try:
             # Hold onto the Renderer lock so we're guaranteed to restore the original
             # screen before any other listener can get a screen write in.
-            print(f"{self.__class__.__name__}: Acquiring lock")
+            logger.info(f"{self.__class__.__name__}: Acquiring lock")
             self.renderer.lock.acquire()
-            print(f"{self.__class__.__name__}: Lock acquired")
+            logger.info(f"{self.__class__.__name__}: Lock acquired")
 
             has_rendered = False
             previous_screen_state = None
             while self.keep_running and self.should_keep_running():
                 if self.hw_inputs.has_any_input():
                     # User has pressed a button, hide the toast
-                    print(f"{self.__class__.__name__}: Exiting due to user input")
+                    logger.info(f"{self.__class__.__name__}: Exiting due to user input")
                     break
 
                 if self._toggle_renderer_lock:
                     # Controller has notified us that another process needs the lock
-                    print(f"{self.__class__.__name__}: Releasing lock")
+                    logger.info(f"{self.__class__.__name__}: Releasing lock")
                     self._toggle_renderer_lock = False
                     self.renderer.lock.release()
 
@@ -155,29 +157,29 @@ def run(self):
                         time.sleep(0.1)
 
                     # Block while waiting to reaquire the lock
-                    print(f"{self.__class__.__name__}: Blocking to re-acquire lock")
+                    logger.info(f"{self.__class__.__name__}: Blocking to re-acquire lock")
                     self.renderer.lock.acquire()
-                    print(f"{self.__class__.__name__}: Lock re-acquired")
+                    logger.info(f"{self.__class__.__name__}: Lock re-acquired")
 
                 if not has_rendered:
                     previous_screen_state = self.renderer.canvas.copy()
-                    print(f"{self.__class__.__name__}: Showing toast")
+                    logger.info(f"{self.__class__.__name__}: Showing toast")
                     self.toast.render()
                     has_rendered = True
 
                 if time.time() - start > self.activation_delay + self.duration and has_rendered:
-                    print(f"{self.__class__.__name__}: Hiding toast")
+                    logger.info(f"{self.__class__.__name__}: Hiding toast")
                     break
 
                 # Free up cpu resources for main thread
                 time.sleep(0.1)
 
         finally:
-            print(f"{self.__class__.__name__}: exiting")
+            logger.info(f"{self.__class__.__name__}: exiting")
             if has_rendered and self.renderer.lock.locked():
                 # As far as we know, we currently hold the Renderer.lock
                 self.renderer.show_image(previous_screen_state)
-                print(f"{self.__class__.__name__}: restored previous screen state")
+                logger.info(f"{self.__class__.__name__}: restored previous screen state")
 
             # We're done, release the lock
             self.renderer.lock.release()
@@ -223,7 +225,7 @@ def __init__(self, action: str, *args, **kwargs):
 
 
     def instantiate_toast(self) -> ToastOverlay:
-        print("instantiating toast!")
+        logger.info("instantiating toast!")
         return ToastOverlay(
             icon_name=SeedSignerIconConstants.MICROSD,
             label_text=self.message,

src/seedsigner/hardware/buttons.py

@@ -1,12 +1,16 @@
+import logging
 from typing import List
 import RPi.GPIO as GPIO
 import time
 
 from seedsigner.models.singleton import Singleton
 
+logger = logging.getLogger(__name__)
+
+
 class HardwareButtons(Singleton):
     if GPIO.RPI_INFO['P1_REVISION'] == 3: #This indicates that we have revision 3 GPIO
-        print("Detected 40pin GPIO (Rasbperry Pi 2 and above)")
+        logger.info("Detected 40pin GPIO (Rasbperry Pi 2 and above)")
         KEY_UP_PIN = 31
         KEY_DOWN_PIN = 35
         KEY_LEFT_PIN = 29
@@ -18,7 +22,7 @@ class HardwareButtons(Singleton):
         KEY3_PIN = 36
 
     else:
-        print("Assuming 26 Pin GPIO (Raspberry P1 1)")
+        logger.info("Assuming 26 Pin GPIO (Raspberry P1 1)")
         KEY_UP_PIN = 5
         KEY_DOWN_PIN = 11
         KEY_LEFT_PIN = 3

src/seedsigner/hardware/microsd.py

@@ -1,10 +1,12 @@
+import logging
 import os
 import time
 
 from seedsigner.models.singleton import Singleton
 from seedsigner.models.threads import BaseThread
 from seedsigner.models.settings import Settings
 
+logger = logging.getLogger(__name__)
 
 
 class MicroSD(Singleton, BaseThread):
@@ -63,7 +65,7 @@ def run(self):
             while self.keep_running:
                 with open(self.FIFO_PATH) as fifo:
                     action = fifo.read()
-                    print(f"fifo message: {action}")
+                    logger.info(f"fifo message: {action}")
 
                     Settings.handle_microsd_state_change(action=action)
                     Controller.get_instance().activate_toast(SDCardStateChangeToastManagerThread(action=action))

src/seedsigner/hardware/pivideostream.py

@@ -1,9 +1,12 @@
 # import the necessary packages
+import logging
 from picamera.array import PiRGBArray
 from picamera import PiCamera
 from threading import Thread
 import time
 
+logger = logging.getLogger(__name__)
+
 
 # Modified from: https://github.com/jrosebr1/imutils
 class PiVideoStream:
@@ -41,7 +44,7 @@ def update(self):
 			# if the thread indicator variable is set, stop the thread
 			# and resource camera resources
 			if self.should_stop:
-				print("PiVideoStream: closing everything")
+				logger.info("PiVideoStream: closing everything")
 				self.stream.close()
 				self.rawCapture.close()
 				self.camera.close()

src/seedsigner/models/decode_qr.py

@@ -912,7 +912,7 @@ def add(self, segment, qr_type=QRType.SIGN_MESSAGE):
 
         # TODO: support formats other than ascii?
         if fmt != "ascii":
-            print(f"Sign message: Unsupported format: {fmt}")
+            logger.info(f"Sign message: Unsupported format: {fmt}")
             return DecodeQRStatus.INVALID
 
         self.complete = True
@@ -1083,7 +1083,7 @@ def add(self, segment, qr_type=QRType.WALLET__GENERIC):
             self.complete = True
             return DecodeQRStatus.COMPLETE
         except Exception as e:
-            print(repr(e))
+            logger.info(repr(e), exc_info=True)
         return DecodeQRStatus.INVALID