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
+logger = logging.getLogger(__name__)
-Controller.get_instance().start()
+
+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 @@ class Controller(Singleton):
             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 @@ class Controller(Singleton):
                     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 @@ class Controller(Singleton):
                     # 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 @@ class Controller(Singleton):
                 # 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}")
+                    logger.info(f"NOT appending {next_destination}")
-                
-                print("-" * 30)
 
         finally:
             from seedsigner.gui.renderer import Renderer
@@ -371,7 +369,7 @@ class Controller(Singleton):
                 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 @@ class Controller(Singleton):
         # 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 @@ class Controller(Singleton):
         
         # 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 @@ class Controller(Singleton):
         """
         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 import Settings
 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 ..components import (Button, FontAwesomeIconConstants, Fonts, FormattedAddr
 from seedsigner.gui.keyboard import Keyboard, TextEntryDisplay
 from seedsigner.hardware.buttons import HardwareButtons, HardwareButtonsConstants
 
+logger = logging.getLogger(__name__)
 
 
 @dataclass
@@ -1412,9 +1414,9 @@ class SeedAddressVerificationScreen(ButtonListScreen):
 
     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 @@ class BaseToastOverlayManagerThread(BaseThread):
 
 
     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 @@ class BaseToastOverlayManagerThread(BaseThread):
                         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 @@ class SDCardStateChangeToastManagerThread(BaseToastOverlayManagerThread):
 
 
     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,3 +1,4 @@
+import logging
 import os
 import time
 
@@ -5,6 +6,7 @@ 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 @@ class MicroSD(Singleton, BaseThread):
             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 @@ class PiVideoStream:
 			# 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 @@ class SignMessageQrDecoder(BaseSingleFrameQrDecoder):
 
         # 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 @@ class GenericWalletQrDecoder(BaseSingleFrameQrDecoder):
             self.complete = True
             return DecodeQRStatus.COMPLETE
         except Exception as e:
-            print(repr(e))
+            logger.info(repr(e), exc_info=True)
         return DecodeQRStatus.INVALID
     
 

src/seedsigner/models/psbt_parser.py

@@ -1,3 +1,4 @@
+import logging
 from binascii import hexlify
 from embit import psbt, script, ec, bip32
 from embit.descriptor import Descriptor
@@ -9,6 +10,7 @@ from typing import List
 from seedsigner.models.seed import Seed
 from seedsigner.models.settings import SettingsConstants
 
+logger = logging.getLogger(__name__)
 
 class OPCODES:
     OP_RETURN = 106
@@ -68,11 +70,11 @@ class PSBTParser():
 
     def parse(self):
         if self.psbt is None:
-            print(f"self.psbt is None!!")
+            logger.info(f"self.psbt is None!!")
             return False
 
         if not self.seed:
-            print("self.seed is None!")
+            logger.info("self.seed is None!")
             return False
 
         self._set_root()

src/seedsigner/models/seed.py

@@ -1,3 +1,4 @@
+import logging
 import unicodedata
 import hashlib
 import hmac
@@ -9,6 +10,8 @@ from typing import List
 
 from seedsigner.models.settings import SettingsConstants
 
+logger = logging.getLogger(__name__)
+
 
 class InvalidSeedException(Exception):
     pass
@@ -46,7 +49,7 @@ class Seed:
         try:
             self.seed_bytes = bip39.mnemonic_to_seed(self.mnemonic_str, password=self._passphrase, wordlist=self.wordlist)
         except Exception as e:
-            print(repr(e))
+            logger.info(repr(e), exc_info=True)
             raise InvalidSeedException(repr(e))
 
 

src/seedsigner/models/settings.py

@@ -1,3 +1,4 @@
+import logging
 import json
 import os
 import platform
@@ -7,6 +8,8 @@ from typing import List
 from seedsigner.models.settings_definition import SettingsConstants, SettingsDefinition
 from seedsigner.models.singleton import Singleton
 
+logger = logging.getLogger(__name__)
+
 
 class InvalidSettingsQRData(Exception):
     pass
@@ -77,7 +80,7 @@ class Settings(Singleton):
             # Replace abbreviated name with full attr_name
             settings_entry = SettingsDefinition.get_settings_entry_by_abbreviated_name(abbreviated_name)
             if not settings_entry:
-                print(f"Ignoring unrecognized attribute: {abbreviated_name}")
+                logger.info(f"Ignoring unrecognized attribute: {abbreviated_name}")
                 continue
 
             # Validate value(s) against SettingsDefinition's valid options
@@ -162,9 +165,9 @@ class Settings(Singleton):
         if attr_name == SettingsConstants.SETTING__PERSISTENT_SETTINGS and value == SettingsConstants.OPTION__DISABLED:
             try:
                 os.remove(self.SETTINGS_FILENAME)
-                print(f"Removed {self.SETTINGS_FILENAME}")
+                logger.info(f"Removed {self.SETTINGS_FILENAME}")
             except:
-                print(f"{self.SETTINGS_FILENAME} not found to be removed")
+                logger.info(f"{self.SETTINGS_FILENAME} not found to be removed")
                 
         self._data[attr_name] = value
         self.save()

src/seedsigner/views/scan_views.py

@@ -1,3 +1,4 @@
+import logging
 import re
 
 from embit.descriptor import Descriptor
@@ -9,6 +10,7 @@ from seedsigner.models.settings import SettingsConstants
 from seedsigner.views.settings_views import SettingsIngestSettingsQRView
 from seedsigner.views.view import BackStackView, ErrorView, MainMenuView, NotYetImplementedView, OptionDisabledView, View, Destination
 
+logger = logging.getLogger(__name__)
 
 
 class ScanView(View):
@@ -111,14 +113,14 @@ class ScanView(View):
                         p = re.compile(r'(\[[0-9,a-f,A-F]+?\/[0-9,\/,h,\']+?\][a-z,A-Z,0-9]*?)([\,,\)])')
                         descriptor_str = p.sub(r'\1/{0,1}/*\2', descriptor_str)
                 except Exception as e:
-                    print(repr(e))
+                    logger.info(repr(e), exc_info=True)
                     descriptor_str = orig_descriptor_str
 
                 descriptor = Descriptor.from_string(descriptor_str)
 
                 if not descriptor.is_basic_multisig:
                     # TODO: Handle single-sig descriptors?
-                    print(f"Received single sig descriptor: {descriptor}")
+                    logger.info(f"Received single sig descriptor: {descriptor}")
                     return Destination(NotYetImplementedView)
 
                 self.controller.multisig_wallet_descriptor = descriptor

src/seedsigner/views/screensaver.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import random
 import time
@@ -9,6 +10,7 @@ from seedsigner.gui.screens.screen import BaseScreen
 from seedsigner.models.settings import Settings
 from seedsigner.models.settings_definition import SettingsConstants
 
+logger = logging.getLogger(__name__)
 
 
 # TODO: This early code is now outdated vis-a-vis Screen vs View distinctions
@@ -178,7 +180,7 @@ class ScreensaverScreen(LogoScreen):
 
             except KeyboardInterrupt as e:
                 # Exit triggered; close gracefully
-                print("Shutting down Screensaver")
+                logger.info("Shutting down Screensaver")
 
                 # Have to let the interrupt bubble up to exit the main app
                 raise e

src/seedsigner/views/seed_views.py

@@ -1,3 +1,4 @@
+import logging
 import embit
 import random
 import time
@@ -25,7 +26,7 @@ from seedsigner.models.settings_definition import SettingsDefinition
 from seedsigner.models.threads import BaseThread, ThreadsafeCounter
 from seedsigner.views.view import NotYetImplementedView, OptionDisabledView, View, Destination, BackStackView, MainMenuView
 
-
+logger = logging.getLogger(__name__)
 
 
 class SeedsMenuView(View):
@@ -1870,7 +1871,7 @@ class SeedAddressVerificationView(View):
         def run(self):
             while self.keep_running:
                 if self.threadsafe_counter.cur_count % 10 == 0:
-                    print(f"Incremented to {self.threadsafe_counter.cur_count}")
+                    logger.info(f"Incremented to {self.threadsafe_counter.cur_count}")
                 
                 i = self.threadsafe_counter.cur_count
 

src/seedsigner/views/tools_views.py

@@ -1,5 +1,6 @@
 from dataclasses import dataclass
 import hashlib
+import logging
 import os
 import time
 
@@ -21,6 +22,7 @@ from seedsigner.views.seed_views import SeedDiscardView, SeedFinalizeView, SeedM
 
 from .view import View, Destination, BackStackView
 
+logger = logging.getLogger(__name__)
 
 
 class ToolsMenuView(View):
@@ -143,7 +145,7 @@ class ToolsImageEntropyMnemonicLengthView(View):
             serial_hash = hashlib.sha256(serial_num)
             hash_bytes = serial_hash.digest()
         except Exception as e:
-            print(repr(e))
+            logger.info(repr(e), exc_info=True)
             hash_bytes = b'0'
 
         # Build in modest entropy via millis since power on

tests/test_main.py

@@ -0,0 +1,40 @@
+import logging
+import sys
+from unittest.mock import patch, call
+
+import pytest
+
+sys.path.insert(0,'src')
+from main import main
+
+
+@patch("main.Controller")
+def test_main__argparse__default(patched_controller):
+    main([])
+    assert logging.root.level == logging.INFO
+    assert logging.getLogger().getEffectiveLevel() == logging.INFO
+    patched_controller.assert_has_calls(
+        [call.get_instance(), call.get_instance().start()]
+    )
+
+
+@patch("main.Controller")
+def test_main__argparse__enable_debug_logging(patched_controller):
+    main(["--loglevel", "DEBUG"])
+    assert logging.root.level == logging.DEBUG
+    assert logging.getLogger().getEffectiveLevel() == logging.DEBUG
+    patched_controller.assert_has_calls(
+        [call.get_instance(), call.get_instance().start()]
+    )
+
+
+def test_main__argparse__invalid_arg():
+    with pytest.raises(SystemExit):
+        main(["--invalid"])
+
+
+@patch("main.Controller")
+def test_main__logging__writes_to_stderr(patched_controller, capsys):
+    main([])
+    _, err = capsys.readouterr()
+    assert "Starting SeedSigner" in err and "INFO" in err