Log message count increases after each reload

[gerardroche]

When plugins use python's built in logging, log messages are duplicated on each reload.

An example is NeoVintageous, https://github.com/NeoVintageous/NeoVintageous/blob/master/lib/nvim.py#L97. Each time the plugin reloaded it reinitialises the logger, so after three reloads you end up with something like:

2017-09-04 17:31:25,466 DEBUG NeoVintageous.lib.state@eval:782 run command action=None, motion=<ViMoveUpByLines (<unset>)>
2017-09-04 17:31:25,466 DEBUG NeoVintageous.lib.state@eval:782 run command action=None, motion=<ViMoveUpByLines (<unset>)>
2017-09-04 17:31:25,466 DEBUG NeoVintageous.lib.state@eval:782 run command action=None, motion=<ViMoveUpByLines (<unset>)>
2017-09-04 17:31:25,466 DEBUG NeoVintageous.lib.state@eval:782 run command action=None, motion=<ViMoveUpByLines (<unset>)>
2017-09-04 17:31:25,481 DEBUG NeoVintageous.lib.state@register:371 '"'
2017-09-04 17:31:25,481 DEBUG NeoVintageous.lib.state@register:371 '"'
2017-09-04 17:31:25,481 DEBUG NeoVintageous.lib.state@register:371 '"'
2017-09-04 17:31:25,481 DEBUG NeoVintageous.lib.state@register:371 '"'

I'm wondering if it's possible for AutomaticPackageReloader to reset/clear any package loggers before reloading.

[randy3k]

I think you can check if a logger has already defined.

if "LOGGING" not in globals():
    LOGGING = True
    _init_logger()

PS: I am not sure if there is sth like logging.hasLogger, such function may avoid the above dirty code. Basically, you don't want to evaluate global expressions twice.

[FichteFoll]

Plugins should remove their added handlers when they are unloaded, imo. Check the PackageDev code for an example (am on mobile).

[randy3k]

That is plugin_unloaded().

[gerardroche]

Removing logger handlers in the plugin_unloaded() hook doesn't work for me when a root module is reloaded. It looks like root modules get reloaded twice, once by ST and once by AutomaticPackageReloader (APR) and this causes some issues.

Part of the issue, I'm guessing, is because my logger initialisation is done in a submodule and ST doesn't reload those properly (and has other side effects I'll explain later). It works for @FichteFoll in PackageDev because the logger initialisation is done in a root module, _logging.py. Whereas in NeoVintageous, the logging initialisation is lazy loaded. It's only done if a debug flag is enabled at startup, and only invoked when a module imports it, which is done via submodules. It's a lot less complicated than it sounds. https://github.com/NeoVintageous/NeoVintageous/blob/15d1bd553a94ef34f9b54af0492936aab7693a8a/lib/nvim.py#L143

A quick workaround for me is to have APR remove any package logger handlers before reloading the package:

gerardroche@649621c

# Clear any package loggers
logger = logging.getLogger(pkg_name)
for handler in list(logger.handlers):
    logger.removeHandler(handler)

That fixes the log messages getting duplicated every reload. There are some other issues though.

One issue is that events get duplicated each time a root module is reloaded. By root module I mean for example the plugin.py module in https://github.com/NeoVintageous/NeoVintageous/blob/15d1bd553a94ef34f9b54af0492936aab7693a8a/plugin.py.

Each time that module is saved and reloaded by APR the events are duplicated just like the log messages were. Like above, it looks like ST and APR are both reloading the module, which is what I think is causing the issue.

[randy3k]

Maybe the easiest (but a bit dirty) solution is to check if it has been initialized or not (assuming the logger does not need to be refreshed).

if "LOGGING" not in globals():
    LOGGING = True
    _init_logger()

[FichteFoll]

Are globals not reset when a module is reloaded?

[randy3k]

The whole module will be re-executed in place, so any global variables which have been defined before will be still available. Just play with

# bar.py
print("bar")

# foo.py
if "FOO" not in globals():
    FOO = True
    print("foo")

>>> import bar
bar
>>> import bar
>>> import imp
>>> imp.reload(bar)
bar
<module 'bar' from '/Users/Randy/Desktop/bar.py'>
>>> import foo
foo
>>> import foo
>>> imp.reload(foo)
<module 'foo' from '/Users/Randy/Desktop/foo.py'>
>>>