Setup Python logging + convert print statements to logger calls

[dbast]

• 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 seedsigner cli entrypoint for main as that 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)

Description

Describe the change simply. Provide a reason for the change.

Include screenshots of any new or modified screens (or at least explain why they were omitted)

This pull request is categorized as a:

• [ ] New feature
• [ ] Bug fix
• [ ] Code refactor
• [ ] Documentation
• [ ] Other

Checklist

• [ ] I’ve run pytest and made sure all unit tests pass before sumbitting the PR

If you modified or added functionality/workflow, did you add new unit tests?

• [ ] No, I’m a fool
• [ ] Yes
• [ ] N/A

I have tested this PR on the following platforms/os:

• [ ] Raspberry Pi OS Manual Build
• [ ] SeedSigner OS on a Pi0/Pi0W board
• [ ] Other

Note: Keep your changes limited in scope; if you uncover other issues or improvements along the way, ideally submit those as a separate PR. The more complicated the PR the harder to review, test, and merge.

[dbast]

yay. green.

[dbast]

rebased

[dbast]

rebased

[jdlcdl]

I'm torn on the concept of logging between:

• should we have more control of logging, especially while debugging (because it's convenient) than simple print messages, and
• should we make sure we never have any print messages and never any logging either.

My worry is that currently, the sdcard is mounted if the user left it in. Add human error (like me not paying attention to remove logging of a mnemonic and passphrase to a debug log before submitting a pr... and it makes it into a persisted file, plus human error like others not paying attention and it gets merged.

Thank you for all of your great prs... and in advance for settling my paranoid (because I don't know better) nerves.

[dbast]

@jdlcdl right... both the existing print statements AND the new logging statements can be problematic IF the console output (stdout/stderr) is redirected to a file on sd-card:

• The now explicit logging config (no usage of logging.basicConfig anymore) and a added unit test ensures that the logging framework is setup to write to stderr.
• Though how seedsigner is started (with or without console redirection to somewhere else) is controlled here https://github.com/SeedSigner/seedsigner-os/blob/main/opt/rootfs-overlay/start.sh#L5 outside of this repo.
• I see the log levels as main advantage of the logging framework over plain print statements: one can de/activate log messages without un-commenting / commenting-out code, by running the main.py via e.g. main.py -l ERROR (no output as all current logger calls are on INFO level) or main.py -l DEBUG (more output, in case we convert the currently commented out print statements to logger.debug(msg) calls, not done by this PR).

• The help message got update to contain a warning in case one changes the default loglevel from INFO to something else:

  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), WARNING: changing the log level to something more verbose than
                        INFO may result in unwanted data being written to stderr

[kdmukai]

Logging > print: ACK

---

Recommend we drop mention of FATAL in the usage and standardize on CRITICAL.

see: https://stackoverflow.com/a/31170408/11611893

Later TODO: Provide explicit style / convention guidance for devs in a README.

[kdmukai]

One thing I can't think through is: what kinds of logging should be INFO vs DEBUG? I think the question is a bit different for us than typical projects since our devs are the only ones who'll ever see any of these messages. So in that sense, EVERY log line is intended to aid debugging.

I guess for now the best we can do is default to INFO and then over time make decisions about what log chatter we want to quiet down and demote to DEBUG.

[kdmukai]

Also filter out WARN?

https://stackoverflow.com/a/15540092/11611893

[kdmukai]

Moving main.py is only successful if the setup has already run python -m pip install -e . (which is not currently in our local dev setup steps in raspberry_pi_os_build_instructions.md; I don't know how SeedSigner OS is setup).

Because main.py is importing from the seedsigner.controller package, EITHER main.py has to sit above the seedsigner package / dir OR the seedsigner module needs to be globally available to import.

I also dislike symlinks in repos in general.

Moving main.py was caused by the desire to add these new tests to the test suite. With maybe the exception of verifying the stderr writes, I don't think the tests are necessary. We don't need to test argparse module's basic functionality and I can live without verifying the log level. Even the verification of stderr is maybe arguably just testing the logging module itself.

I'm reading up on logging.ini configs now. Having the output explicitly stated there (plus some other needed config, e.g. silencing PIL) tentatively feels preferable.

[dbast]

@kdmukai Added another commit that 1. moves the main.py back 2. eliminates the introduced symlink 3. still gets the added tests working by doing an import trick :)

I cautiously converted all existing print statements to logging.info and set the INFO log level as default log level to mimic the current behaviour of the print statements... further PRs can then refine the level of each message and also enable the currently commented-out print statements on e.g. debug level.... this PR is intended more on finding agreement regarding the overall concept

[kdmukai]

Final minor nits noted above, but otherwise very happy to ACK this!

Very nice quality-of-life improvement here, @dbast.

[newtonick]

tACK. Great contribution as usual @dbast!