Logs generated during loading of extensions are not output

[djmattyg007]

In the latest release, the logs generated by mopidy.ext.load_extensions() are not output anywhere. From what I can tell, this is because that function is called before logging is set up further down the main() function.

This makes it very difficult to diagnose issues related to individual extensions not being loaded. I'm trying to revive the API Explorer extension and found this while trying to get it to load.

[kingosticks]

They work fine for me, we handle this in log.bootstrap_delayed_logging().

It is mostly DEBUG level logging in mopidy.ext.load_extensions() which will not be output by default. Have you adjusted the logging verbosity appropriately e.g. mopidy -v ?

[djmattyg007]

I set logging.verbosity to 2 in the config file, and it doesn't seem to work. I manually inserted the following code just above _delayed_handler.release(), and it always prints an empty list:

from pprint import pprint
pprint(_delayed_handler._buffer)

[kingosticks]

I set logging.verbosity to 2 in the config file, and it doesn't seem to work.

I've just done exactly this (snippet below) for both config files and tried both the service and also running as my user on the command line, and I'm afraid I still can't reproduce this. Also, looking at the Mopidy code, I also can't explain why your above snippet wouldn't print a bunch of the delayed log statements, can you?

[logging]
verbosity = 2

Is it just the load_extensions() stuff missing or are you also missing the non-debug version log message e.g.

INFO 2021-01-07 22:46:16,701 [8264:MainThread] mopidy.main
Starting Mopidy 3.1.1-2-g0121ad0a

[djmattyg007]

I don't see the version log message either. The first debug log messages I see with verbosity set to 2 are the "validating extension" messages, like so:

DEBUG    2021-01-08 09:12:51,983 [1252944:MainThread] mopidy.ext                                   
  Validating extension: file

The first non-debug log message I see is the list of enabled extensions:

INFO     2021-01-08 09:12:52,133 [1252944:MainThread] mopidy.__main__                              
  Enabled extensions: advanced_scrobbler, api_explorer, youtube, softwaremixer, http, musicbox_webclient, local, stream, m3u

I'm this running on python3.8 as an unprivileged user manually from the CLI with the following invocation:

mopidy --config path/to/mopidy.conf

[djmattyg007]

Probably also worth mentioning that I'm running this inside of a virtualenv that was created like so:

python3 -m venv --system-site-packages .

[djmattyg007]

I've found the issue, and will have a PR ready shortly.