Reloading Addons Doesn't fully unregister modules

I have a very simple project so far, just the out-of-box __init__.py and auto_load.py, and then i've added Debug.py and GUI_Panel.py. I've pasted my code below. I also have Reload On Save enabled. Every time I save, I unregister X times and register X+1 times. For some reason, the addon is being duplicated. In Blender, there's still only 1 tab, though I believe that's because the ids are the same, so they wouldn't duplicate. Oddly, I can disable and enable the addon from Blender's preferences menu and i get X unregisters and X registers, so I do believe the issue resides here somewhere.

Debug.py

import sys
import logging

__all__ = ("Debug")

class Debug:
    class __Singleton:
        logger = None

        def __init__(self):
            logLevel = logging.DEBUG
            formatter = logging.Formatter(
                '%(asctime)s - %(levelname)s - %(message)s')

            consoleHandler = logging.StreamHandler(sys.stdout)
            consoleHandler.setLevel(logLevel)
            consoleHandler.setFormatter(formatter)

            self.logger = logging.getLogger(__name__)
            self.logger.setLevel(logLevel)
            self.logger.addHandler(consoleHandler)

    instance = None

    def __init__(self):
        if not Debug.instance:
            Debug.instance = Debug.__Singleton()

    def Log(self, message: str) -> None:
        Debug.instance.logger.debug(message)

    def LogInfo(self, message: str) -> None:
        Debug.instance.logger.info(message)

    def LogWarning(self, message: str) -> None:
        Debug.instance.logger.warning(message)

    def LogError(self, message: str) -> None:
        Debug.instance.logger.error(message)

    def LogCritical(self, message: str) -> None:
        Debug.instance.logger.critical(message)

GUI_Panel.py

import bpy as blenderpy
from .Debug import Debug

_debug = Debug()

class GUI_Panel(blenderpy.types.Panel):
    bl_label = "Character Frame"
    bl_idname = "OBJECT_PT_character_frame"
    bl_space_type = "VIEW_3D"
    bl_region_type = "UI"
    bl_category = "Character Frame"

    @classmethod
    def poll(cls, context):
        return context.mode in {"OBJECT", "EDIT_MESH", "PAINT_WEIGHT", "POSE"}

    def draw(self, context):
        self.layout.label(text="Hello World")

def register():
    _debug.Log("Loading GUI_Panel")

def unregister():
    _debug.Log("Unloading GUI_Panel")

That's interesting. I just looked into it a bit and made the following observations:

When reloading, register is only called once. Therefore, _debug.Log("Loading GUI_Panel") is only called once. However, this one call prints multiple times. This is self.logger.addHandler(consoleHandler) has been called on the same logger multiple times. The logger is still the same after reloading, because it is cached by logging.getLogger(__name__). Reloading won't remove the logger.

Disabling and enabling the addon in the user preferences actually has the same issue. However, you probably did not notice it, for two reasons. First, you did not change the addon. In that case, Blender will just call register again, without any reloading. Second, auto_load.py does not do any reloading. It will just import the modules. Therefore, you'd have to implement the reloading yourself:

if "bpy" in locals():
    import importlib
    importlib.reload(Debug)
    importlib.reload(GUI_Panel)
else:
    from . import Debug
    from . import GUI_Panel

import bpy

def register():
    GUI_Panel.register()

def unregister():
    GUI_Panel.unregister()

When "fixing" both things, you'll see that your original issue is back.

The best solution to your problem, that I've found so far is to do this:

if not self.logger.hasHandlers():
    self.logger.addHandler(consoleHandler)

This will make sure that you don't add the handler more than once.

Just for your information: The way the vscode extension does reloading is by letting Python forget about all of your addon modules by removing them from sys.modules. Then they will be loaded again when you import them. I found this to work more reliably than reloading modules in-place, which can lead to fairly hard to find issues.

Thank you for the detailed reply! Good to see it was my own error that caused the issue.

The solution you provided almost fixed my issue. For some reason, logger.hasHandlers() always returned true, so it was no longer adding my own handler to it. Instead, I'm using len(logger.handlers) <= 1 which appears to have fixed the issue so far. Not super elegant, but I suppose I can deal with it.

import sys
import logging

class Debug:
    logger = None

    @staticmethod
    def Init():
        logLevel = logging.DEBUG
        formatter = logging.Formatter(
            '%(asctime)s - %(levelname)s - %(message)s')

        Debug.logger = logging.getLogger(__name__)
        Debug.logger.setLevel(logLevel)

        if len(Debug.logger.handlers) <= 1:
            consoleHandler = logging.StreamHandler(sys.stdout)
            consoleHandler.setLevel(logLevel)
            consoleHandler.setFormatter(formatter)
            Debug.logger.addHandler(consoleHandler)

    @staticmethod
    def Log(message: str) -> None:
        Debug.logger.debug(message)

    @staticmethod
    def LogInfo(message: str) -> None:
        Debug.logger.info(message)

    @staticmethod
    def LogWarning(message: str) -> None:
        Debug.logger.warning(message)

    @staticmethod
    def LogError(message: str) -> None:
        Debug.logger.error(message)

    @staticmethod
    def LogCritical(message: str) -> None:
        Debug.logger.critical(message)

Good, I think we can close this for now then.

JacquesLucke / blender_vscode

Reloading Addons Doesn't fully unregister modules #77