Setup Python logging + convert print statements to logger calls #558

dbast · 2024-05-15T19:28:21Z

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:

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 · 2024-05-15T19:29:57Z

yay. green.

dbast · 2024-07-04T09:34:10Z

rebased

* 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) ```

dbast · 2024-07-05T18:39:26Z

rebased

jdlcdl · 2024-07-05T21:35:01Z

src/seedsigner/main.py

+    )
+
+    args = parser.parse_args(sys_argv)
+    logging.basicConfig(


That there is no "filename" param, does this guarantee (even into the future) that messages logged will always end up on stdout?

hm... how to guarantee this? The Python stdlib logging framework since forever logs to stderr if nothing else is given to the logging.basicConfig() call. A change of behaviour like logging to a not further specified file would be a huge break for many many applications that handle secrets, credentials, tokens etc.

Added a unit test in a1d3489 that actually verifies that the log is written to the stderr.

stderr, of course, thank you for the correction.

And that it would raise alarms elsewhere eases my mind.

yay. the added testcase is now green. and I also replaced the logging.basicConfig with explicit calls to have better control over what is exactly setup here.

jdlcdl · 2024-07-05T21:37:55Z

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 · 2024-07-07T17:41:29Z

@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

jdlcdl · 2024-07-07T21:46:45Z

tests/test_main.py

+
+
+@patch("seedsigner.main.Controller")
+def test_main__logging__writes_to_stderr(patched_controller, capsys):


kdmukai · 2024-07-08T13:30:23Z

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 · 2024-07-08T13:30:35Z

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 · 2024-07-08T14:26:14Z

Also filter out WARN?

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

kdmukai · 2024-07-08T14:46:05Z

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 · 2024-07-08T15:49:50Z

@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

src/main.py

kdmukai · 2024-07-08T17:28:06Z

src/main.py

+    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")


Note: the .%(msecs)03d is redundant as asctime includes millis already.

I'd find something like this format more useful:

"%(asctime)s %(levelname)5s [%(name)s %(funcName)s (%(lineno)d)]: %(message)s"

2024-07-08 18:25:01,437 INFO [__main__ main (45)]: Starting Seedsigner with: {'loglevel': 'INFO'} 2024-07-08 18:25:06,255 INFO [seedsigner.controller activate_toast (428)]: Controller: starting RemoveSDCardToastManagerThread 2024-07-08 18:25:06,512 INFO [seedsigner.gui.toast run (124)]: RemoveSDCardToastManagerThread: started 2024-07-08 18:25:06,514 INFO [seedsigner.controller start (308)]: back_stack: [] 2024-07-08 18:25:06,519 INFO [seedsigner.controller start (312)]: Executing MainMenuView() 2024-07-08 18:25:09,577 INFO [seedsigner.gui.toast run (136)]: RemoveSDCardToastManagerThread: Acquiring lock 2024-07-08 18:25:09,582 INFO [seedsigner.gui.toast run (138)]: RemoveSDCardToastManagerThread: Lock acquired 2024-07-08 18:25:09,589 INFO [seedsigner.gui.toast run (166)]: RemoveSDCardToastManagerThread: Showing toast 2024-07-08 18:25:11,799 INFO [seedsigner.gui.toast run (145)]: RemoveSDCardToastManagerThread: Exiting due to user input 2024-07-08 18:25:11,804 INFO [seedsigner.gui.toast run (178)]: RemoveSDCardToastManagerThread: exiting 2024-07-08 18:25:11,856 INFO [seedsigner.gui.toast run (182)]: RemoveSDCardToastManagerThread: restored previous screen state 2024-07-08 18:25:12,243 INFO [seedsigner.controller start (358)]: Appending next destination: ToolsMenuView() 2024-07-08 18:25:12,247 INFO [seedsigner.controller start (363)]: ------------------------------ 2024-07-08 18:25:12,252 INFO [seedsigner.controller start (308)]: back_stack: [ 0: ToolsMenuView() ] 2024-07-08 18:25:12,259 INFO [seedsigner.controller start (312)]: Executing ToolsMenuView()

uh. thanks for the redundant msec finding, don't know why i didn't see that... this seems to have changed, I remember that is was required when working with older Python versions... having msecs help to accurately see how much time is required between certain calls.

Good idea to add funcname + lineno etc to the log line... (I am used to have all those fields via json loggers, which are not feasible here for the console) ... went for "%(asctime)s %(levelname)8s [%(name)s %(funcName)s (%(lineno)d)]: %(message)s" (=changed the 5s to 8s spacing so that all the potential loglevel are right aligned .. longest name is CRITICAL), see 5a4ae50

tests/test_main.py

src/seedsigner/controller.py

tests/test_main.py

src/main.py

kdmukai · 2024-07-13T16:38:05Z

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

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

newtonick · 2024-07-15T03:42:52Z

tACK. Great contribution as usual @dbast!

dbast force-pushed the logging branch from c44bcd0 to a26abd2 Compare July 4, 2024 09:34

dbast force-pushed the logging branch from a26abd2 to 8e9c120 Compare July 5, 2024 18:39

jdlcdl reviewed Jul 5, 2024

View reviewed changes

Warn about log level changes in cli arg description

94dc795

dbast force-pushed the logging branch from 7b7220d to ac212a5 Compare July 6, 2024 15:31

dbast marked this pull request as draft July 6, 2024 15:34

dbast added 2 commits July 7, 2024 17:54

Test that logging actually writes to stderr

5881a6e

Replace logging.basicConfig with explicit calls

2d9960e

dbast force-pushed the logging branch from ac212a5 to 2d9960e Compare July 7, 2024 17:18

dbast marked this pull request as ready for review July 7, 2024 17:20

jdlcdl reviewed Jul 7, 2024

View reviewed changes

tests/test_main.py

@patch("seedsigner.main.Controller")

def test_main__logging__writes_to_stderr(patched_controller, capsys):

Copy link

jdlcdl Jul 7, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

<3

Move back main.py

3ff2951

kdmukai reviewed Jul 8, 2024

View reviewed changes

src/main.py Show resolved Hide resolved

Add possibility to set per module default log levels

af2cdf8

kdmukai reviewed Jul 8, 2024

View reviewed changes

tests/test_main.py Outdated Show resolved Hide resolved

kdmukai reviewed Jul 8, 2024

View reviewed changes

src/seedsigner/controller.py Outdated Show resolved Hide resolved

Use human readable loglevel names in test

f2ae4bb

kdmukai reviewed Jul 8, 2024

View reviewed changes

src/seedsigner/controller.py Outdated Show resolved Hide resolved

dbast added 5 commits July 9, 2024 08:37

Remove separator line

0c9d955

Add newline to back_stack logging

19c4d1f

Refine logformat

5a4ae50

Update test

c13a8b8

Merge remote-tracking branch 'origin/dev' into logging

44d92c9

kdmukai reviewed Jul 13, 2024

View reviewed changes

tests/test_main.py Outdated Show resolved Hide resolved

kdmukai reviewed Jul 13, 2024

View reviewed changes

src/main.py Outdated Show resolved Hide resolved

Improve test maintainability, camel case

d088fbd

newtonick approved these changes Jul 15, 2024

View reviewed changes

newtonick merged commit 80ad7d6 into SeedSigner:dev Jul 15, 2024
2 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Setup Python logging + convert print statements to logger calls #558

Setup Python logging + convert print statements to logger calls #558

dbast commented May 15, 2024

dbast commented May 15, 2024

dbast commented Jul 4, 2024

dbast commented Jul 5, 2024

jdlcdl Jul 5, 2024

dbast Jul 6, 2024

jdlcdl Jul 6, 2024

dbast Jul 7, 2024

jdlcdl commented Jul 5, 2024 •

edited

Loading

dbast commented Jul 7, 2024

jdlcdl Jul 7, 2024

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

dbast commented Jul 8, 2024

kdmukai Jul 8, 2024

dbast Jul 9, 2024

kdmukai commented Jul 13, 2024

newtonick commented Jul 15, 2024



		@patch("seedsigner.main.Controller")
		def test_main__logging__writes_to_stderr(patched_controller, capsys):

Setup Python logging + convert print statements to logger calls #558

Setup Python logging + convert print statements to logger calls #558

Conversation

dbast commented May 15, 2024

Description

Checklist

dbast commented May 15, 2024

dbast commented Jul 4, 2024

dbast commented Jul 5, 2024

jdlcdl Jul 5, 2024

Choose a reason for hiding this comment

dbast Jul 6, 2024

Choose a reason for hiding this comment

jdlcdl Jul 6, 2024

Choose a reason for hiding this comment

dbast Jul 7, 2024

Choose a reason for hiding this comment

jdlcdl commented Jul 5, 2024 • edited Loading

dbast commented Jul 7, 2024

jdlcdl Jul 7, 2024

Choose a reason for hiding this comment

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

kdmukai commented Jul 8, 2024

dbast commented Jul 8, 2024

kdmukai Jul 8, 2024

Choose a reason for hiding this comment

dbast Jul 9, 2024

Choose a reason for hiding this comment

kdmukai commented Jul 13, 2024

newtonick commented Jul 15, 2024

jdlcdl commented Jul 5, 2024 •

edited

Loading