Improve logging #80

jayqi · 2021-09-19T21:49:28Z

Improves logging for nbautoexport to make things easier to troubleshoot.

There are three scenarios of use, each of which will have logging that works differently, in order of likely relevance to users:

Running with Jupyter app. The logger is set to the Jupyter server logger, which we grab via a traitlets convenience method. This will log things with consistent formatting as the rest of Jupyter's logs with pretty colors.
Using nbautoexport CLI. The logger named "nbautoexport" is used, and configured with a stream handler that will print to console. The --verbose/-v flag is now a counter instead of a boolean flag.
- Default will print typer.echo statements and sets log level to WARNING.
- -v is INFO log level.
- -vv is DEBUG log level.
Importing as library. (This isn't something users will likely do, but it is possible so this is implemented for completeness.) The logger named "nbautoexport" is used, and set with a null handler. This is best practice so that the nbautoexport logger will inherit the users' desired configuration from the root logger.

One change looking for feedback:

Before: Runtime error in post-save hook (e.g., if .nbautoexport config is invalid) would fail loudly (popup in Jupyter UI, see example)
After: Will not do anything in Jupyter UI but will still log error to the server logs

Examples of logs from Jupyter Lab

Successful startup

Jupyter Lab

Jupyter Notebook

Failed startup

Successful export

Jupyter Lab

Jupyter Notebook

.nbautoexport validation error

Export with debug mode

Example of CLI verbosity levels

Example of importing as library

demo_logging.py

import logging
from pathlib import Path

from nbautoexport.export import export_notebook
from nbautoexport.sentinel import NbAutoexportConfig

print("---DEFAULT---")

logger = logging.getLogger()
logging.basicConfig()
export_notebook(Path("notebooks/Untitled.ipynb"), NbAutoexportConfig())

print("---INFO---")

logger.setLevel(logging.INFO)
export_notebook(Path("notebooks/Untitled.ipynb"), NbAutoexportConfig())

print("---DEBUG---")

logger.setLevel(logging.DEBUG)
export_notebook(Path("notebooks/Untitled.ipynb"), NbAutoexportConfig())

Output:

---DEFAULT---
---INFO---
INFO:nbautoexport:nbautoexport | Exporting notebooks/Untitled.ipynb ...
---DEBUG---
INFO:nbautoexport:nbautoexport | Exporting notebooks/Untitled.ipynb ...
DEBUG:nbautoexport:nbautoexport | Using export configuration:
{
  "export_formats": [
    "script"
  ],
  "organize_by": "extension",
  "clean": {
    "exclude": []
  }
}
DEBUG:traitlets:Loading script exporter: python
DEBUG:traitlets:Applying preprocessor: TagRemovePreprocessor
DEBUG:traitlets:Applying preprocessor: RegexRemovePreprocessor

codecov · 2021-09-19T21:53:24Z

Codecov Report

Merging #80 (1d9c13b) into master (f539250) will increase coverage by 0.4%.
The diff coverage is 98.5%.

@@           Coverage Diff            @@
##           master     #80     +/-   ##
========================================
+ Coverage    98.1%   98.5%   +0.4%     
========================================
  Files           8       8             
  Lines         382     425     +43     
========================================
+ Hits          375     419     +44     
+ Misses          7       6      -1

Impacted Files	Coverage Δ
nbautoexport/jupyter_config.py	`97.1% <95.4%> (+0.6%)`	⬆️
nbautoexport/__init__.py	`100.0% <100.0%> (ø)`
nbautoexport/export.py	`95.8% <100.0%> (+0.9%)`	⬆️
nbautoexport/nbautoexport.py	`99.2% <100.0%> (+0.8%)`	⬆️
nbautoexport/sentinel.py	`100.0% <100.0%> (ø)`
nbautoexport/utils.py	`100.0% <100.0%> (ø)`

github-actions · 2021-09-19T21:53:45Z

🚀 Deployed on https://deploy-preview-80--zen-roentgen-1e5a72.netlify.app

klwetstone · 2021-09-20T14:09:11Z

@jayqi Looks very helpful! I installed it from the new branch and had no issues. A couple questions for my own understanding:

Is the idea that we will still set up nbautoexport the same, but when there is an error we'll (1) get more information in the logs, and (2) can manually save out the notebook in debug mode in either python or the nbautoexport cli to get more info (per the exampling of importing as library and CLI verbosity levels sections)?
How do we set the notebook to export with debug mode when running with the jupyter app - adding -vv to the nbautoexport configure command?

jayqi · 2021-09-20T14:45:10Z

@klwetstone

Is the idea that we will still set up nbautoexport the same, but when there is an error we'll (1) get more information in the logs

Yes.

can manually save out the notebook in debug mode in either python or the nbautoexport cli to get more info (per the exampling of importing as library and CLI verbosity levels sections)

No, this is mainly just for completeness. You could always invoke nbautoexport as a library or (more commonly) with the CLI command. This just makes sure the logs behave in ways that Python devs expect if you were to do those things.

How do we set the notebook to export with debug mode when running with the jupyter app

You can run jupyter lab --debug or jupyter notebook --debug to get more logs than you ever wanted.

r-b-g-b

This is excellent! One tiny tiny suggestion related to what is logged at specific levels during installation. Here's the outputs for different possible states at different log levels:

Not already installed:

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install -v
2021-10-01 09:50:44,793 - nbautoexport - INFO - Installing post-save hook.
2021-10-01 09:50:44,793 - nbautoexport - INFO - nbautoexport post-save hook installed.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install -vv
2021-10-01 09:51:06,471 - nbautoexport - DEBUG - Detected existing Jupyter configuration at /home/robert/.jupyter/jupyter_notebook_config.py
2021-10-01 09:51:06,471 - nbautoexport - INFO - Installing post-save hook.
2021-10-01 09:51:06,471 - nbautoexport - INFO - nbautoexport post-save hook installed.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

Already installed:

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install -v
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install -vv
2021-10-01 09:49:21,364 - nbautoexport - DEBUG - Detected existing Jupyter configuration at /home/robert/.jupyter/jupyter_notebook_config.py
2021-10-01 09:49:21,365 - nbautoexport - DEBUG - Detected existing nbautoexport post-save hook.
2021-10-01 09:49:21,366 - nbautoexport - DEBUG - Existing post-save hook is version 0.3.1+32.g5d71683
2021-10-01 09:49:21,366 - nbautoexport - DEBUG - No changes made.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

Already installed different version:

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) ✗ nbautoexport install -v
2021-10-01 09:56:38,983 - nbautoexport - INFO - Updating nbautoexport post-save hook with version 0.3.1+32.g5d71683...
2021-10-01 09:56:38,984 - nbautoexport - INFO - nbautoexport post-save hook installed.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) ✗ nbautoexport install -vv
2021-10-01 09:56:51,727 - nbautoexport - DEBUG - Detected existing Jupyter configuration at /home/robert/.jupyter/jupyter_notebook_config.py
2021-10-01 09:56:51,727 - nbautoexport - DEBUG - Detected existing nbautoexport post-save hook.
2021-10-01 09:56:51,729 - nbautoexport - DEBUG - Existing post-save hook is version 0.2.1+32.g5d71683
2021-10-01 09:56:51,729 - nbautoexport - INFO - Updating nbautoexport post-save hook with version 0.3.1+32.g5d71683...
2021-10-01 09:56:51,730 - nbautoexport - INFO - nbautoexport post-save hook installed.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

For the "Already installed" state, the output for no verbosity flag and -v are the same. Besides that, as a user, I might expect that nbautoexport install -v would tell me whether it's installing or whether it detects an existing installation. My suggestion would just be to promote:

nbautoexport/nbautoexport/jupyter_config.py

Line 97 in 5d71683

logger.debug("Detected existing nbautoexport post-save hook.")

nbautoexport/nbautoexport/jupyter_config.py

Line 116 in 5d71683

logger.debug("No changes made.")

from debug to info. Then the output for nbautoexport install -v would be:

(nbautoexport-dev) ➜  nbautoexport git:(74-improve-logging) nbautoexport install -v
2021-10-01 09:49:21,364 - nbautoexport - INFO - Detected existing Jupyter configuration at /home/robert/.jupyter/jupyter_notebook_config.py
2021-10-01 09:49:21,366 - nbautoexport - INFO - No changes made.
nbautoexport post-save hook successfully installed with Jupyter.
If a Jupyter server is already running, you will need to restart it for nbautoexport to work.

nbautoexport/__init__.py

jayqi · 2021-10-01T19:00:27Z

Thanks for the review @r-b-g-b, I incorporated your suggestions.

r-b-g-b

Awesome!

jayqi added 8 commits September 19, 2021 11:13

Add notebooks/ to .gitignore for manual testing

2f3497b

Set up logger that switches configuration appropriately

be893b8

Logging in initialize block

33c0ca2

More debug logging in post_save

96625c5

Remove unnecessary config option that was generating warning

0124c05

Change version injection since f-strings break format method

2393cc4

Don't print relative path since it's more fragile

88fc76a

Set nbconvert to use same log handlers for consistent formatting

d6e5343

jayqi linked an issue Sep 19, 2021 that may be closed by this pull request

Improve startup/runtime logging #74

Closed

jayqi added 2 commits September 19, 2021 17:51

Polish for export logging

bd205fa

Make verbosity a counter and add to all commands

96e7c3f

jayqi added 15 commits September 19, 2021 19:51

Move logger setup to callback to avoid import side effects

9c85363

Don't use traitlets.log.get_logger because it caches

69b4ee7

get_logger tests

0f05a20

Update post_save initialization tests with logs

55dcf18

Add log testing to test_post_save

4efb121

Add test for verbosity

a5c6f13

Increase specificity from traitlets Application to JupyterApp

6d5153b

Update changelog

3dc365d

Docs polish

2fa44ca

Write to stderr instead of print

11726e7

Test double import error in initialization

b304c80

Properly escape metacharacters on re.sub

c0af2b0

Fix mypy error since redefinition in different block level

1142354

Add test for post_save error

69d112a

Update changelog

5d71683

jayqi marked this pull request as ready for review September 20, 2021 12:29

jayqi requested a review from r-b-g-b September 20, 2021 12:31

jayqi requested review from ejm714, pjbull and klwetstone September 20, 2021 12:31

r-b-g-b requested changes Oct 1, 2021

View reviewed changes

nbautoexport/__init__.py Show resolved Hide resolved

nbautoexport/__init__.py Show resolved Hide resolved

Promote some logger statements from debug to info

1d9c13b

jayqi force-pushed the 74-improve-logging branch from 190d083 to 1d9c13b Compare October 1, 2021 18:35

jayqi requested a review from r-b-g-b October 1, 2021 19:00

r-b-g-b approved these changes Oct 1, 2021

View reviewed changes

jayqi merged commit dd57020 into master Oct 1, 2021

jayqi deleted the 74-improve-logging branch October 1, 2021 19:33

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logging #80

Improve logging #80

jayqi commented Sep 19, 2021 •

edited

Loading

codecov bot commented Sep 19, 2021 •

edited

Loading

github-actions bot commented Sep 19, 2021 •

edited

Loading

klwetstone commented Sep 20, 2021

jayqi commented Sep 20, 2021 •

edited by r-b-g-b

Loading

r-b-g-b left a comment

jayqi commented Oct 1, 2021

r-b-g-b left a comment

Improve logging #80

Improve logging #80

Conversation

jayqi commented Sep 19, 2021 • edited Loading

Examples of logs from Jupyter Lab

Successful startup

Jupyter Lab

Jupyter Notebook

Failed startup

Successful export

Jupyter Lab

Jupyter Notebook

.nbautoexport validation error

Export with debug mode

Example of CLI verbosity levels

Example of importing as library

codecov bot commented Sep 19, 2021 • edited Loading

Codecov Report

github-actions bot commented Sep 19, 2021 • edited Loading

klwetstone commented Sep 20, 2021

jayqi commented Sep 20, 2021 • edited by r-b-g-b Loading

r-b-g-b left a comment

Choose a reason for hiding this comment

Not already installed:

Already installed:

Already installed different version:

jayqi commented Oct 1, 2021

r-b-g-b left a comment

Choose a reason for hiding this comment

jayqi commented Sep 19, 2021 •

edited

Loading

codecov bot commented Sep 19, 2021 •

edited

Loading

github-actions bot commented Sep 19, 2021 •

edited

Loading

jayqi commented Sep 20, 2021 •

edited by r-b-g-b

Loading