A lot of noise being generated in docs builds

[steppi]

Description

https://github.com/scipy/scipy/issues/20277 points out that adding jupyterlite-sphinx to SciPy introduced a lot of noise in the docs builds. I've found that part of the problem is the hardcoding of --debug here in the invocation to jupyter lite build

https://github.com/jupyterlite/jupyterlite-sphinx/blob/09be95849eaf7bba1287fc95e56c49360526ad40/jupyterlite_sphinx/jupyterlite_sphinx.py#L576-L580

I'm still trying to trace through what the other sources of noise are. Here's what it looks like for a toy project I created

[jupyterlite-sphinx] Running JupyterLite build
static:jupyter-lite.json
.  pre_status:static:jupyter-lite.json
    tarball:         jupyterlite-app-0.2.1.tgz 9MB
    output:          /home/birbir/interactive_doc_experiments/doc/build/html/lite
    lite dir:        /home/birbir/interactive_doc_experiments/doc/source
    apps:            notebooks, edit, lab, repl, tree, consoles
    sourcemaps:      True
    unused packages: True
archive:archive
contents:contents
icons:icons
jupyterlite-pyodide-kernel-pyodide:pyodide
lite:jupyter-lite.json
mimetypes:jupyter-lite.json
serve:contents
settings:overrides
translation:translation
.  status:archive:archive
[LiteBuildApp] No archive (yet): source-jupyterlite.tgz
.  status:contents:contents
    contents: 2 files
.  status:icons:icons
    favicon files: 0 files
.  status:jupyterlite-pyodide-kernel-pyodide:pyodide
     URL: None
 archive: []
   cache: 0 files
   local: 0 files
.  status:lite:jupyter-lite.json
[LiteBuildApp]     jupyter-lite.(json|ipynb): 0 files
.  status:mimetypes:jupyter-lite.json
    filetypes:         26 
.  status:serve:contents
    url: http://127.0.0.1:8000/
    server: tornado
    headers:
.  status:settings:overrides
    overrides.json: 0
.  status:translation:translation
    translation files: 0 files
static:output_dir
.  pre_init:static:output_dir
static:unpack
.  init:static:unpack
/home/birbir/.virtualenvs/scipy-interactive-docs/lib/python3.10/site-packages/jupyterlite_core/addons/base.py:294: UserWarning: install libarchive-c for better performance when working with archives: No module named 'libarchive'
  return has_optional_dependency(
federated_extensions:copy:ext:jupyterlab_pygments
federated_extensions:copy:ext:jupyterlab-jupytext
federated_extensions:copy:ext:@jupyterlite/pyodide-kernel-extension
.  pre_build:federated_extensions:copy:ext:jupyterlab_pygments
.  pre_build:federated_extensions:copy:ext:jupyterlab-jupytext
.  pre_build:federated_extensions:copy:ext:@jupyterlite/pyodide-kernel-extension
contents:copy:c0052505_8d88_491e_af76_b9d2ab9b0416.ipynb
contents:copy:e60fb639_76a6_4796_91d4_13db74db8306.ipynb
icons:copy
translation:copy
.  build:contents:copy:c0052505_8d88_491e_af76_b9d2ab9b0416.ipynb
.  build:contents:copy:e60fb639_76a6_4796_91d4_13db74db8306.ipynb
.  build:icons:copy
.  build:translation:copy
contents:contents:.
federated_extensions:patch
federated_extensions:settings
jupyterlite-pyodide-kernel-piplite:patch
mimetypes:patch
.  post_build:contents:contents:.
.  post_build:federated_extensions:patch
.  post_build:federated_extensions:settings
.  post_build:jupyterlite-pyodide-kernel-piplite:patch
.  post_build:mimetypes:patch
[jupyterlite-sphinx] JupyterLite build done
build succeeded, 1 warning.

those build:contents:copy:*.ipynb notebooks are painful for SciPy where many notebooks are generated. I'm working on identifying all of the sources of these logging messages and would like to put them behind a debug flag somehow, defaulting to not showing them.

[steppi]

I've identified that some of the noise seems to come from status methods in jupyterlite_core/addons/* like here:

    def status(self, manager):
        """yield some status information about the state of contents"""
        yield self.task(
            name="contents",
            actions=[
                lambda: self.log.debug(
                    "[lite] [contents] All Contents %s",
                    pprint.pformat([str(p[0]) for p in self.file_src_dest]),
                ),
                lambda: print(f"""    contents: {len(list(self.file_src_dest))} files"""),
            ],
        )

I'm not sure at a glance whether there's a convenient way to suppress these.

[steppi]

I've set the logging level to warn in the call to jupyter lite build in jupyterlite_sphinx.py, and replaced all of the prints in the status methods mentioned above with log.info and am now down to the following level of output when building my toy package. A bit stumped on where the other things are coming from. Will keep working on it.

[jupyterlite-sphinx] Running JupyterLite build
.  pre_status:static:jupyter-lite.json
.  status:archive:archive
.  status:contents:contents
.  status:icons:icons
.  status:jupyterlite-pyodide-kernel-pyodide:pyodide
     URL: None
 archive: []
   cache: 0 files
   local: 0 files
.  status:lite:jupyter-lite.json
.  status:mimetypes:jupyter-lite.json
.  status:serve:contents
.  status:settings:overrides
.  status:translation:translation
.  pre_init:static:output_dir
.  init:static:unpack
.  pre_build:federated_extensions:copy:ext:jupyterlab_pygments
.  pre_build:federated_extensions:copy:ext:jupyterlab-jupytext
.  pre_build:federated_extensions:copy:ext:@jupyterlite/pyodide-kernel-extension
.  build:contents:copy:d034dfd2_4dd1_468b_bf8d_a8e694184439.ipynb
.  build:contents:copy:e60fb639_76a6_4796_91d4_13db74db8306.ipynb
.  build:icons:copy
.  build:translation:copy
.  post_build:contents:contents:.
.  post_build:federated_extensions:patch
.  post_build:federated_extensions:settings
.  post_build:jupyterlite-pyodide-kernel-piplite:patch
.  post_build:mimetypes:patch
[jupyterlite-sphinx] JupyterLite build done

[steppi]

Huh, I threw in a print statement to check the log level

    def status(self, manager):
        """yield some status information about the state of contents"""
        print("****************")
        print(self.log)
        yield self.task(
            name="contents",
            actions=[
                lambda: self.log.debug(
                    "[lite] [contents] All Contents %s",
                    pprint.pformat([str(p[0]) for p in self.file_src_dest]),
                ),
                lambda: self.log.info(f"""    contents: {len(list(self.file_src_dest))} files"""),
            ],
        )

and its coming back as <Logger LiteBuildApp (DEBUG)>. This level is WARNING in other places though and many of the LiteBuildApp log messages are being suppressed. I'm having trouble figuring out where logging level is being changed.

[steppi]

OK, this is pretty strange.

The LiteStatusApp class which controls these status messages inherits in a chain up to the ancestor JupyterApp which inherits from traitlets.config.application.Application.

JupyterApp sets it's default log level to INFO

class JupyterApp(Application):
    """Base class for Jupyter applications"""

    name = "jupyter"  # override in subclasses
    description = "A Jupyter Application"

    aliases = base_aliases
    flags = base_flags

    def _log_level_default(self) -> int:
        return logging.INFO

but if I do

from jupyter_core import JupyterApp

a = JupyterApp()

print(a.trait_values())

the output is

{'_loaded_config_files': [],
 'answer_yes': False,
 'argv': [],
 'cli_config': {},
 'config': {},
 'config_dir': '/home/birbir/.jupyter',
 'config_file': '',
 'config_file_name': 'jupyter_config',
 'data_dir': '/home/birbir/.local/share/jupyter',
 'examples': '',
 'extra_args': [],
 'generate_config': False,
 'jupyter_path': ['/home/birbir/.virtualenvs/scipy-interactive-docs/share/jupyter',
  '/home/birbir/.local/share/jupyter',
  '/usr/local/share/jupyter',
  '/usr/share/jupyter'],
 'keyvalue_description': "The command-line option below sets the respective configurable class-parameter:\n    --Class.parameter=value\nThis line is evaluated in Python, so simple expressions are allowed.\nFor instance, to set `C.a=[0,1,2]`, you may type this:\n    --C.a='range(3)'",
 'log': <Logger JupyterApp (DEBUG)>,
 'log_datefmt': '%Y-%m-%d %H:%M:%S',
 'log_format': '[%(name)s]%(highlevel)s %(message)s',
 'log_level': 20,
 'logging_config': {},
 'option_description': 'The options below are convenience aliases to configurable class-options,\nas listed in the "Equivalent to" description-line of the aliases.\nTo see all configurable class-options for some <cmd>, use:\n    <cmd> --help-all',
 'parent': None,
 'raise_config_file_errors': False,
 'runtime_dir': '/home/birbir/.local/share/jupyter/runtime',
 'show_config': False,
 'show_config_json': False,
 'subapp': None,
 'subcommand': '',
 'subcommand_description': "\nSubcommands are launched as `{app} cmd [args]`. For information on using\nsubcommand 'cmd', do: `{app} cmd -h`.\n",
 'subcommands': {},
 'version': '0.0'}

which means that self.log is logging at a DEBUG level, despite log_level being correctly set to the default level.

[steppi]

Sorry, self.log being at DEBUG was a red herring. This noise is coming from doit being used in jupyterlite_core. It looks like the verbosity is set to 2.

[steppi]

OK, I've verified that changing these lines in jupyterlite-core/jupyterlite_core/manager.py from

    @default("_doit_config")
    def _default_doit_config(self):
        """our hardcoded ``DOIT_CONFIG``"""
        return {
            "dep_file": ".jupyterlite.doit.db",
            "backend": "sqlite3",
            "verbosity": 2,
        }

to

    @default("_doit_config")
    def _default_doit_config(self):
        """our hardcoded ``DOIT_CONFIG``"""
        return {
            "dep_file": ".jupyterlite.doit.db",
            "backend": "sqlite3",
            "verbosity": 0,
            "reporter": "zero",
        }

(together with setting the logging level to warn in the invocation of jupyter lite build, and removing unguarded prints from the addons in jupyterlite_core.)

successfully suppresses all of the noise.

Can we make suppressing the noise the default?

[steppi]

It turns out that we can suppress most of the noise by changing the invocation of jupyter lite build to be

         command = [
             "jupyter",
             "lite",
+            "doit"
             "build",
-            "--debug",
             *config,
             *contents,
             "--contents",
             os.path.join(app.srcdir, CONTENT_DIR),
             "--output-dir",
             os.path.join(app.outdir, JUPYTERLITE_DIR),
             *apps_option,
             "--lite-dir",
             jupyterlite_dir,
+            "--log-level",
+            "WARN",
+            "--",
+            "--verbosity",
+            "0",
+            "--reporter",
+            "zero",
         ]

         subprocess.run(command, cwd=app.srcdir, check=True)

Thanks to @bollwyvl for the tip.

@martinRenou, @jtpio, @Carreau, any objections towards making this the default behavior in jupyterlite-sphinx. I was thinking maybe we could put the current invocation

        command = [
            "jupyter",
            "lite",
            "build",
            "--debug",
            *config,
            *contents,
            "--contents",
            os.path.join(app.srcdir, CONTENT_DIR),
            "--output-dir",
            os.path.join(app.outdir, JUPYTERLITE_DIR),
            *apps_option,
            "--lite-dir",
            jupyterlite_dir,
        ]

        subprocess.run(command, cwd=app.srcdir, check=True)

behind a jupyterlite_debug option in conf.py which defaults to False.

[Carreau]

+1 to decrease verbosity levels, I do have some time this week, and will try to catch up with your work and help you on this and having a numpy docs build

[jtpio]

@martinRenou, @jtpio, @Carreau, any objections towards making this the default behavior in jupyterlite-sphinx. I was thinking maybe we could put the current invocation

Sounds good, and we can document how to enable more logs (opt-in).

[steppi]

This is fixed by #153