From 8e9c1207bd7d4d91401c28d954408b6989555200 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Fri, 5 Jul 2024 20:38:55 +0200 Subject: [PATCH 01/12] Setup Python logging + convert print statements to logger calls * Setup the standard Python logging module via main.py with cli argument so that different log levels can be chosen. * Move the main.py into ./src/seedsigner folder, to be able to importable for unit-testing. * Also define a cli entrypoint for main as the becomes possible with the main.py move. * Create a symlink from./src/main.py -> ./src/seedsigner/main.py so that seedsigner can be started without any changes to seedsigner-os * Add uni-tests for the main.py regarding the default log level and changing the log level. * Converts all existing print statements to `logger.info` calls (INFO is the default log level) * Produces tab aligned log message like `2024-05-15 17:21:45.385 INFO: Starting Seedsigner with: {'loglevel': 'INFO'}` * The sub seconds display + the option to choose the loglevel help to debug the application and also see how long certain code needs There are many many commented out `print` statements in the code base that could be converted to `logger.debug(...)` calls and thus be shown additionally via running `main.py -l DEBUG`, but that is for next PRs as all those commented out print statements can be potential broken by referencing non existing variables etc. This is a move towards more Pythonic ways of doing: The logging framework with its central configurability, options to set levels, the ability to activate certain log lines by choosing a different log level (without un-commenting/commenting print statements), the possibility to the see how much times is between log calls (without extra instrumenting the code) etc is all in all very convenient. The help output on cli: ``` usage: main.py [-h] [-l {CRITICAL,FATAL,ERROR,WARN,WARNING,INFO,DEBUG,NOTSET}] options: -h, --help show this help message and exit -l {CRITICAL,FATAL,ERROR,WARN,WARNING,INFO,DEBUG,NOTSET}, --loglevel {CRITICAL,FATAL,ERROR,WARN,WARNING,INFO,DEBUG,NOTSET} Set the log level (default: INFO) ``` --- pyproject.toml | 3 ++ src/main.py | 5 +-- src/seedsigner/controller.py | 28 +++++++-------- src/seedsigner/gui/components.py | 5 ++- src/seedsigner/gui/screens/seed_screens.py | 6 ++-- src/seedsigner/gui/toast.py | 28 ++++++++------- src/seedsigner/hardware/buttons.py | 8 +++-- src/seedsigner/hardware/microsd.py | 4 ++- src/seedsigner/hardware/pivideostream.py | 5 ++- src/seedsigner/main.py | 37 ++++++++++++++++++++ src/seedsigner/models/decode_qr.py | 4 +-- src/seedsigner/models/psbt_parser.py | 6 ++-- src/seedsigner/models/seed.py | 5 ++- src/seedsigner/models/settings.py | 9 +++-- src/seedsigner/views/scan_views.py | 6 ++-- src/seedsigner/views/screensaver.py | 4 ++- src/seedsigner/views/seed_views.py | 5 +-- src/seedsigner/views/tools_views.py | 4 ++- tests/test_main.py | 40 ++++++++++++++++++++++ 19 files changed, 160 insertions(+), 52 deletions(-) mode change 100644 => 120000 src/main.py create mode 100755 src/seedsigner/main.py create mode 100644 tests/test_main.py diff --git a/pyproject.toml b/pyproject.toml index 002bfe2cd..cae52be04 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -15,6 +15,9 @@ readme = "README.md" requires-python = ">=3.10" version = "0.8.0-rc1" +[project.scripts] +seedsigner = "seedsigner.main:main" + [project.urls] "Bug Tracker" = "https://github.com/SeedSigner/seedsigner/issues" Homepage = "https://seedsigner.com/" diff --git a/src/main.py b/src/main.py deleted file mode 100644 index 740faf30a..000000000 --- a/src/main.py +++ /dev/null @@ -1,4 +0,0 @@ -from seedsigner.controller import Controller - -# Get the one and only Controller instance and start our main loop -Controller.get_instance().start() diff --git a/src/main.py b/src/main.py new file mode 120000 index 000000000..9adb9fd98 --- /dev/null +++ b/src/main.py @@ -0,0 +1 @@ +seedsigner/main.py \ No newline at end of file diff --git a/src/seedsigner/controller.py b/src/seedsigner/controller.py index 37d80e479..d777bdea7 100644 --- a/src/seedsigner/controller.py +++ b/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"back_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,12 @@ 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}") + logger.info(f"NOT appending {next_destination}") - print("-" * 30) + logger.info("-" * 30) finally: from seedsigner.gui.renderer import Renderer @@ -371,7 +371,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 +385,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 +397,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 +416,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() diff --git a/src/seedsigner/gui/components.py b/src/seedsigner/gui/components.py index 2046f4e17..0706f2139 100644 --- a/src/seedsigner/gui/components.py +++ b/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 diff --git a/src/seedsigner/gui/screens/seed_screens.py b/src/seedsigner/gui/screens/seed_screens.py index 9fe35c1c7..9c6464b67 100644 --- a/src/seedsigner/gui/screens/seed_screens.py +++ b/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 @@ -1411,9 +1413,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) diff --git a/src/seedsigner/gui/toast.py b/src/seedsigner/gui/toast.py index 7a07f30bc..d21ff02c9 100644 --- a/src/seedsigner/gui/toast.py +++ b/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, diff --git a/src/seedsigner/hardware/buttons.py b/src/seedsigner/hardware/buttons.py index 8d42105d0..6fecc10fa 100644 --- a/src/seedsigner/hardware/buttons.py +++ b/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 diff --git a/src/seedsigner/hardware/microsd.py b/src/seedsigner/hardware/microsd.py index 26065c03e..da545b7f8 100644 --- a/src/seedsigner/hardware/microsd.py +++ b/src/seedsigner/hardware/microsd.py @@ -1,3 +1,4 @@ +import logging import os import time @@ -5,6 +6,7 @@ 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)) diff --git a/src/seedsigner/hardware/pivideostream.py b/src/seedsigner/hardware/pivideostream.py index cb3031b33..06a1ebb7d 100644 --- a/src/seedsigner/hardware/pivideostream.py +++ b/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() diff --git a/src/seedsigner/main.py b/src/seedsigner/main.py new file mode 100755 index 000000000..1b331509f --- /dev/null +++ b/src/seedsigner/main.py @@ -0,0 +1,37 @@ +#!/usr/bin/env python + +import argparse +import logging +import sys + +from seedsigner.controller import Controller + +logger = logging.getLogger(__name__) + + +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)', + ) + + args = parser.parse_args(sys_argv) + logging.basicConfig( + level=logging.getLevelName(args.loglevel), + format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + + 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:]) diff --git a/src/seedsigner/models/decode_qr.py b/src/seedsigner/models/decode_qr.py index 78ded320d..55991668a 100644 --- a/src/seedsigner/models/decode_qr.py +++ b/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 diff --git a/src/seedsigner/models/psbt_parser.py b/src/seedsigner/models/psbt_parser.py index a20c13cc1..fa481c801 100644 --- a/src/seedsigner/models/psbt_parser.py +++ b/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 seedsigner.models.seed import Seed from seedsigner.models.settings import SettingsConstants +logger = logging.getLogger(__name__) class PSBTParser(): @@ -62,11 +64,11 @@ def _set_root(self): 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() diff --git a/src/seedsigner/models/seed.py b/src/seedsigner/models/seed.py index 51eb85553..411825084 100644 --- a/src/seedsigner/models/seed.py +++ b/src/seedsigner/models/seed.py @@ -1,3 +1,4 @@ +import logging import unicodedata from binascii import hexlify @@ -7,6 +8,8 @@ from seedsigner.models.settings import SettingsConstants +logger = logging.getLogger(__name__) + class InvalidSeedException(Exception): pass @@ -44,7 +47,7 @@ def _generate_seed(self) -> bool: 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)) diff --git a/src/seedsigner/models/settings.py b/src/seedsigner/models/settings.py index f0b1c97f0..ae5b4ffe7 100644 --- a/src/seedsigner/models/settings.py +++ b/src/seedsigner/models/settings.py @@ -1,3 +1,4 @@ +import logging import json import os import platform @@ -7,6 +8,8 @@ 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 @@ def parse_settingsqr(cls, data: str) -> tuple[str, dict]: # 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 @@ def set_value(self, attr_name: str, value: any): 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() diff --git a/src/seedsigner/views/scan_views.py b/src/seedsigner/views/scan_views.py index 7bac9a459..1b923efa0 100644 --- a/src/seedsigner/views/scan_views.py +++ b/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.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 @@ def run(self): 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 diff --git a/src/seedsigner/views/screensaver.py b/src/seedsigner/views/screensaver.py index 960df6c8d..84476da47 100644 --- a/src/seedsigner/views/screensaver.py +++ b/src/seedsigner/views/screensaver.py @@ -1,3 +1,4 @@ +import logging import os import random import time @@ -9,6 +10,7 @@ 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 @@ def start(self): 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 diff --git a/src/seedsigner/views/seed_views.py b/src/seedsigner/views/seed_views.py index 9ec874dad..628dbf5c0 100644 --- a/src/seedsigner/views/seed_views.py +++ b/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.threads import BaseThread, ThreadsafeCounter from seedsigner.views.view import NotYetImplementedView, OptionDisabledView, View, Destination, BackStackView, MainMenuView - +logger = logging.getLogger(__name__) class SeedsMenuView(View): @@ -1778,7 +1779,7 @@ def __init__(self, address: str, seed: Seed, descriptor: Descriptor, script_type 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 diff --git a/src/seedsigner/views/tools_views.py b/src/seedsigner/views/tools_views.py index 02c34f230..83290fb3b 100644 --- a/src/seedsigner/views/tools_views.py +++ b/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 .view import View, Destination, BackStackView +logger = logging.getLogger(__name__) class ToolsMenuView(View): @@ -143,7 +145,7 @@ def run(self): 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 diff --git a/tests/test_main.py b/tests/test_main.py new file mode 100644 index 000000000..4f18632a3 --- /dev/null +++ b/tests/test_main.py @@ -0,0 +1,40 @@ +import pytest +from unittest.mock import patch, call + +# Must import this before anything else that imports the Controller +import base + +from seedsigner.main import main + + +@patch("seedsigner.main.logging.basicConfig") +@patch("seedsigner.main.Controller") +def test_main__argparse__default(patched_controller, patched_logging): + main([]) + patched_logging.assert_called_once_with( + level=20, + format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + patched_controller.assert_has_calls( + [call.get_instance(), call.get_instance().start()] + ) + + +@patch("seedsigner.main.logging.basicConfig") +@patch("seedsigner.main.Controller") +def test_main__argparse__enable_debug_logging(patched_controller, patched_logging): + main(["--loglevel", "DEBUG"]) + patched_logging.assert_called_once_with( + level=10, + format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + patched_controller.assert_has_calls( + [call.get_instance(), call.get_instance().start()] + ) + + +def test_main__argparse__invalid_arg(): + with pytest.raises(SystemExit): + main(["--invalid"]) From 94dc7959cde80e9a341abd0755803a5477e424ea Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Sat, 6 Jul 2024 17:14:23 +0200 Subject: [PATCH 02/12] Warn about log level changes in cli arg description --- src/seedsigner/main.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/seedsigner/main.py b/src/seedsigner/main.py index 1b331509f..868609ef8 100755 --- a/src/seedsigner/main.py +++ b/src/seedsigner/main.py @@ -17,7 +17,11 @@ def main(sys_argv=None): choices=list((logging._nameToLevel.keys())), default="INFO", type=str, - help='Set the log level (default: %(default)s)', + 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) @@ -26,7 +30,6 @@ def main(sys_argv=None): format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", datefmt="%Y-%m-%d %H:%M:%S", ) - logger.info(f"Starting Seedsigner with: {args.__dict__}") # Get the one and only Controller instance and start our main loop From 5881a6e3fa83885df15293f5adbf1e91d114de1a Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Sat, 6 Jul 2024 17:15:03 +0200 Subject: [PATCH 03/12] Test that logging actually writes to stderr --- pyproject.toml | 1 + tests/test_main.py | 7 +++++++ 2 files changed, 8 insertions(+) diff --git a/pyproject.toml b/pyproject.toml index cae52be04..dc6142541 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -61,6 +61,7 @@ branch = true [tool.pytest.ini_options] testpaths = ["tests"] +addopts = "-p no:logging" [tool.setuptools] include-package-data = true diff --git a/tests/test_main.py b/tests/test_main.py index 4f18632a3..46a41d9eb 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -38,3 +38,10 @@ def test_main__argparse__enable_debug_logging(patched_controller, patched_loggin def test_main__argparse__invalid_arg(): with pytest.raises(SystemExit): main(["--invalid"]) + + +@patch("seedsigner.main.Controller") +def test_main__logging__writes_to_stderr(patched_controller, capsys): + main([]) + _, err = capsys.readouterr() + assert "INFO: Starting Seedsigner with: {'loglevel': 'INFO'}" in err From 2d9960ea5a2b772c4ce3b2328a329bfe274ba3db Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Sat, 6 Jul 2024 17:25:21 +0200 Subject: [PATCH 04/12] Replace logging.basicConfig with explicit calls --- src/seedsigner/main.py | 12 ++++++++---- tests/test_main.py | 25 ++++++++----------------- 2 files changed, 16 insertions(+), 21 deletions(-) diff --git a/src/seedsigner/main.py b/src/seedsigner/main.py index 868609ef8..8746c538a 100755 --- a/src/seedsigner/main.py +++ b/src/seedsigner/main.py @@ -25,11 +25,15 @@ def main(sys_argv=None): ) args = parser.parse_args(sys_argv) - logging.basicConfig( - level=logging.getLevelName(args.loglevel), - format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", - datefmt="%Y-%m-%d %H:%M:%S", + + root_logger = logging.getLogger() + root_logger.setLevel(logging.getLevelName(args.loglevel)) + console_handler = logging.StreamHandler(sys.stderr) + console_handler.setFormatter( + logging.Formatter("%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s") ) + root_logger.addHandler(console_handler) + logger.info(f"Starting Seedsigner with: {args.__dict__}") # Get the one and only Controller instance and start our main loop diff --git a/tests/test_main.py b/tests/test_main.py index 46a41d9eb..8b499dcef 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -1,35 +1,26 @@ +import logging + import pytest from unittest.mock import patch, call -# Must import this before anything else that imports the Controller -import base - from seedsigner.main import main -@patch("seedsigner.main.logging.basicConfig") @patch("seedsigner.main.Controller") -def test_main__argparse__default(patched_controller, patched_logging): +def test_main__argparse__default(patched_controller): main([]) - patched_logging.assert_called_once_with( - level=20, - format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", - datefmt="%Y-%m-%d %H:%M:%S", - ) + assert logging.root.level == 20 + assert logging.getLogger().getEffectiveLevel() == 20 patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] ) -@patch("seedsigner.main.logging.basicConfig") @patch("seedsigner.main.Controller") -def test_main__argparse__enable_debug_logging(patched_controller, patched_logging): +def test_main__argparse__enable_debug_logging(patched_controller): main(["--loglevel", "DEBUG"]) - patched_logging.assert_called_once_with( - level=10, - format="%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s", - datefmt="%Y-%m-%d %H:%M:%S", - ) + assert logging.root.level == 10 + assert logging.getLogger().getEffectiveLevel() == 10 patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] ) From 3ff2951ad0c23ff36833767814c9b55d38cb2266 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Mon, 8 Jul 2024 17:35:41 +0200 Subject: [PATCH 05/12] Move back main.py --- pyproject.toml | 3 --- src/main.py | 45 +++++++++++++++++++++++++++++++++++++++++- src/seedsigner/main.py | 44 ----------------------------------------- tests/test_main.py | 12 ++++++----- 4 files changed, 51 insertions(+), 53 deletions(-) mode change 120000 => 100755 src/main.py delete mode 100755 src/seedsigner/main.py diff --git a/pyproject.toml b/pyproject.toml index dc6142541..ee1855442 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -15,9 +15,6 @@ readme = "README.md" requires-python = ">=3.10" version = "0.8.0-rc1" -[project.scripts] -seedsigner = "seedsigner.main:main" - [project.urls] "Bug Tracker" = "https://github.com/SeedSigner/seedsigner/issues" Homepage = "https://seedsigner.com/" diff --git a/src/main.py b/src/main.py deleted file mode 120000 index 9adb9fd98..000000000 --- a/src/main.py +++ /dev/null @@ -1 +0,0 @@ -seedsigner/main.py \ No newline at end of file diff --git a/src/main.py b/src/main.py new file mode 100755 index 000000000..8746c538a --- /dev/null +++ b/src/main.py @@ -0,0 +1,44 @@ +#!/usr/bin/env python + +import argparse +import logging +import sys + +from seedsigner.controller import Controller + +logger = logging.getLogger(__name__) + + +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.%(msecs)03d %(levelname)s:\t%(message)s") + ) + root_logger.addHandler(console_handler) + + 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:]) diff --git a/src/seedsigner/main.py b/src/seedsigner/main.py deleted file mode 100755 index 8746c538a..000000000 --- a/src/seedsigner/main.py +++ /dev/null @@ -1,44 +0,0 @@ -#!/usr/bin/env python - -import argparse -import logging -import sys - -from seedsigner.controller import Controller - -logger = logging.getLogger(__name__) - - -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.%(msecs)03d %(levelname)s:\t%(message)s") - ) - root_logger.addHandler(console_handler) - - 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:]) diff --git a/tests/test_main.py b/tests/test_main.py index 8b499dcef..22f051b4c 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -1,12 +1,14 @@ import logging +import sys +from unittest.mock import patch, call import pytest -from unittest.mock import patch, call -from seedsigner.main import main +sys.path.insert(0,'src') +from main import main -@patch("seedsigner.main.Controller") +@patch("main.Controller") def test_main__argparse__default(patched_controller): main([]) assert logging.root.level == 20 @@ -16,7 +18,7 @@ def test_main__argparse__default(patched_controller): ) -@patch("seedsigner.main.Controller") +@patch("main.Controller") def test_main__argparse__enable_debug_logging(patched_controller): main(["--loglevel", "DEBUG"]) assert logging.root.level == 10 @@ -31,7 +33,7 @@ def test_main__argparse__invalid_arg(): main(["--invalid"]) -@patch("seedsigner.main.Controller") +@patch("main.Controller") def test_main__logging__writes_to_stderr(patched_controller, capsys): main([]) _, err = capsys.readouterr() From af2cdf80369d67d3053046ef649fb74c28ff4f67 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Mon, 8 Jul 2024 19:25:53 +0200 Subject: [PATCH 06/12] Add possibility to set per module default log levels --- src/main.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/main.py b/src/main.py index 8746c538a..bf8a8d798 100755 --- a/src/main.py +++ b/src/main.py @@ -8,6 +8,11 @@ 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() @@ -34,6 +39,10 @@ def main(sys_argv=None): ) 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 From f2ae4bb3383aaf17061a977d8276bf31d4bb6684 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Mon, 8 Jul 2024 19:51:02 +0200 Subject: [PATCH 07/12] Use human readable loglevel names in test --- tests/test_main.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_main.py b/tests/test_main.py index 22f051b4c..231039b2c 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -11,7 +11,7 @@ @patch("main.Controller") def test_main__argparse__default(patched_controller): main([]) - assert logging.root.level == 20 + assert logging.root.level == logging.INFO assert logging.getLogger().getEffectiveLevel() == 20 patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] @@ -21,7 +21,7 @@ def test_main__argparse__default(patched_controller): @patch("main.Controller") def test_main__argparse__enable_debug_logging(patched_controller): main(["--loglevel", "DEBUG"]) - assert logging.root.level == 10 + assert logging.root.level == logging.DEBUG assert logging.getLogger().getEffectiveLevel() == 10 patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] From 0c9d955f3fde3ff4b2a449eb86242f216cded1a6 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Tue, 9 Jul 2024 08:37:59 +0200 Subject: [PATCH 08/12] Remove separator line --- src/seedsigner/controller.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/seedsigner/controller.py b/src/seedsigner/controller.py index d777bdea7..4672d469e 100644 --- a/src/seedsigner/controller.py +++ b/src/seedsigner/controller.py @@ -359,8 +359,6 @@ def run(self): self.back_stack.append(next_destination) else: logger.info(f"NOT appending {next_destination}") - - logger.info("-" * 30) finally: from seedsigner.gui.renderer import Renderer From 19c4d1f4bdaecf292472187adc048c98ed57abb4 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Tue, 9 Jul 2024 08:39:58 +0200 Subject: [PATCH 09/12] Add newline to back_stack logging --- src/seedsigner/controller.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/seedsigner/controller.py b/src/seedsigner/controller.py index 4672d469e..6243955ff 100644 --- a/src/seedsigner/controller.py +++ b/src/seedsigner/controller.py @@ -305,7 +305,7 @@ def run(self): self.psbt_parser = None self.psbt_seed = None - logger.info(f"back_stack: {self.back_stack}") + logger.info(f"\nback_stack: {self.back_stack}") try: # Instantiate the View class and run it From 5a4ae50cf0210d489bc7d0e2ac5b447c577a3b48 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Tue, 9 Jul 2024 09:03:53 +0200 Subject: [PATCH 10/12] Refine logformat --- src/main.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main.py b/src/main.py index bf8a8d798..f6357efb6 100755 --- a/src/main.py +++ b/src/main.py @@ -35,7 +35,7 @@ def main(sys_argv=None): root_logger.setLevel(logging.getLevelName(args.loglevel)) console_handler = logging.StreamHandler(sys.stderr) console_handler.setFormatter( - logging.Formatter("%(asctime)s.%(msecs)03d %(levelname)s:\t%(message)s") + logging.Formatter("%(asctime)s %(levelname)8s [%(name)s %(funcName)s (%(lineno)d)]: %(message)s") ) root_logger.addHandler(console_handler) From c13a8b84a4b4d789518111b7a8a568a3c19839fb Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Tue, 9 Jul 2024 11:54:08 +0200 Subject: [PATCH 11/12] Update test --- tests/test_main.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_main.py b/tests/test_main.py index 231039b2c..16a431377 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -37,4 +37,4 @@ def test_main__argparse__invalid_arg(): def test_main__logging__writes_to_stderr(patched_controller, capsys): main([]) _, err = capsys.readouterr() - assert "INFO: Starting Seedsigner with: {'loglevel': 'INFO'}" in err + assert " INFO [main main (46)]: Starting Seedsigner with: {'loglevel': 'INFO'}" in err From d088fbdb42cba66cba848e70c5da959a171d1624 Mon Sep 17 00:00:00 2001 From: Daniel Bast <2790401+dbast@users.noreply.github.com> Date: Sat, 13 Jul 2024 21:07:59 +0200 Subject: [PATCH 12/12] Improve test maintainability, camel case --- src/main.py | 2 +- tests/test_main.py | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/main.py b/src/main.py index f6357efb6..c6888267c 100755 --- a/src/main.py +++ b/src/main.py @@ -43,7 +43,7 @@ def main(sys_argv=None): for module, level in DEFAULT_MODULE_LOG_LEVELS.items(): logging.getLogger(module).setLevel(level) - logger.info(f"Starting Seedsigner with: {args.__dict__}") + logger.info(f"Starting SeedSigner with: {args.__dict__}") # Get the one and only Controller instance and start our main loop Controller.get_instance().start() diff --git a/tests/test_main.py b/tests/test_main.py index 16a431377..f4e48fc82 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -12,7 +12,7 @@ def test_main__argparse__default(patched_controller): main([]) assert logging.root.level == logging.INFO - assert logging.getLogger().getEffectiveLevel() == 20 + assert logging.getLogger().getEffectiveLevel() == logging.INFO patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] ) @@ -22,7 +22,7 @@ def test_main__argparse__default(patched_controller): def test_main__argparse__enable_debug_logging(patched_controller): main(["--loglevel", "DEBUG"]) assert logging.root.level == logging.DEBUG - assert logging.getLogger().getEffectiveLevel() == 10 + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG patched_controller.assert_has_calls( [call.get_instance(), call.get_instance().start()] ) @@ -37,4 +37,4 @@ def test_main__argparse__invalid_arg(): def test_main__logging__writes_to_stderr(patched_controller, capsys): main([]) _, err = capsys.readouterr() - assert " INFO [main main (46)]: Starting Seedsigner with: {'loglevel': 'INFO'}" in err + assert "Starting SeedSigner" in err and "INFO" in err