Add configurable log level

CHANGELOG.md

@@ -2,6 +2,14 @@
 
 ## Unreleased
 
+### Added
+
+- You can now configure VS code internal log level using [`blender.addon.logLevel`](vscode://settings/blender.addon.logLevel) and [`blender.addon.logLevelGlobal`](vscode://settings/blender.addon.logLevelGlobal) (#198)
+  - to mute logs set log level to critical
+  - to enable more logs set log level to debug
+  - changing log level required blender restart
+  - logs now have colors
+
 ## [0.0.23] - 2024-09-06
 
 ### Added

README.md

@@ -156,6 +156,8 @@ This addon has some ability to help with [Blender source code development](https
 - Use the latest Blender version from https://www.blender.org/download/.
 - Check [CHANGELOG](./CHANGELOG.md) for breaking changes.
 - Search Issues for similar problems.
+  - when reporting issue please enable debug logs using [`blender.addon.logLevel`](vscode://settings/blender.addon.logLevel) 
+    and [`blender.addon.logLevelGlobal`](vscode://settings/blender.addon.logLevelGlobal) 
 - Look in VS Code output window.
 
 ## Status

package.json

@@ -258,6 +258,20 @@
                 "--factory-startup"
               ]
             ]
+          },
+          "blender.addon.logLevel": {
+            "type": "string",
+            "scope": "resource",
+            "description": "Log level for blender_vscode extension inside Blender. Debug is most verbose.",
+            "default": "info",
+            "enum": ["debug", "info", "warning", "error", "critical"]
+          },
+          "blender.addon.logLevelGlobal": {
+            "type": "string",
+            "scope": "resource",
+            "description": "Log level for 3rd party modules in blender_vscode extension. Debug is most verbose.",
+            "default": "warning",
+            "enum": ["debug", "info", "warning", "error", "critical"]
           }
         }
       }

pythonFiles/include/blender_vscode/__init__.py

@@ -5,6 +5,10 @@
 
 import bpy
 
+from . import log
+
+LOG = log.getLogger()
+
 
 @dataclass
 class AddonInfo:

pythonFiles/include/blender_vscode/communication.py

@@ -1,21 +1,26 @@
+import random
+import threading
 import time
+from functools import partial
 from typing import Callable, Dict
 
-import flask
 import debugpy
-import random
+import flask
 import requests
-import threading
-from functools import partial
-from .utils import run_in_main_thread
+
 from .environment import blender_path, scripts_folder, python_path
+from .utils import run_in_main_thread
+from . import log
+
+LOG = log.getLogger()
 
 EDITOR_ADDRESS = None
 OWN_SERVER_PORT = None
 DEBUGPY_PORT = None
 
-server = flask.Flask("Blender Server")
-post_handlers = {}
+SERVER = flask.Flask("Blender Server")
+log.configure_flask_log(SERVER)
+POST_HANDLERS = {}
 
 
 def setup(address: str, path_mappings):
@@ -27,9 +32,9 @@ def setup(address: str, path_mappings):
 
     send_connection_information(path_mappings)
 
-    print("Waiting for debug client.")
+    LOG.info("Waiting for debug client.")
     debugpy.wait_for_client()
-    print("Debug client attached.")
+    LOG.info("Debug client attached.")
 
 
 def start_own_server():
@@ -39,7 +44,7 @@ def server_thread_function():
         while True:
             try:
                 port[0] = get_random_port()
-                server.run(debug=True, port=port[0], use_reloader=False)
+                SERVER.run(debug=True, port=port[0], use_reloader=False)
             except OSError:
                 pass
 
@@ -71,30 +76,38 @@ def start_debug_server():
 #########################################
 
 
-@server.route("/", methods=["POST"])
+@SERVER.route("/", methods=["POST"])
 def handle_post():
     data = flask.request.get_json()
-    print("Got POST:", data)
+    LOG.debug(f"Got POST: {data}")
 
-    if data["type"] in post_handlers:
-        return post_handlers[data["type"]](data)
+    if data["type"] in POST_HANDLERS:
+        return POST_HANDLERS[data["type"]](data)
+    else:
+        LOG.warning(f"Unhandled POST: {data}")
 
     return "OK"
 
 
-@server.route("/", methods=["GET"])
+@SERVER.route("/", methods=["GET"])
 def handle_get():
     data = flask.request.get_json()
-    print("Got GET:", data)
+    LOG.debug(f"Got GET: {str(data)}")
 
     if data["type"] == "ping":
         pass
+    elif data["type"] == "complete":
+        from .blender_complete import complete
+
+        return {"items": complete(data)}
+    else:
+        LOG.warning(f"Unhandled GET: {data}")
     return "OK"
 
 
 def register_post_handler(type: str, handler: Callable):
-    assert type not in post_handlers, post_handlers
-    post_handlers[type] = handler
+    assert type not in POST_HANDLERS, POST_HANDLERS
+    POST_HANDLERS[type] = handler
 
 
 def register_post_action(type: str, handler: Callable):
@@ -123,7 +136,7 @@ def send_connection_information(path_mappings: Dict):
 
 
 def send_dict_as_json(data):
-    print("Sending:", data)
+    LOG.debug(f"Sending: {data}")
     requests.post(EDITOR_ADDRESS, json=data)
 
 

pythonFiles/include/blender_vscode/environment.py

@@ -1,11 +1,30 @@
+import logging
+import os
+import sys
+from pathlib import Path
 from typing import Optional
 
-import bpy
-import sys
 import addon_utils
-from pathlib import Path
-import platform
-import os
+import bpy
+
+_str_to_log_level = {
+    "debug-with-flask": logging.DEBUG,
+    "debug": logging.DEBUG,
+    "info": logging.INFO,
+    "warning": logging.WARNING,
+    "error": logging.ERROR,
+    "critical": logging.CRITICAL,
+}
+
+
+def _parse_log(env_var_name: str) -> int:
+    log_env_global = os.environ.get(env_var_name, "info") or "info"
+    try:
+        return _str_to_log_level[log_env_global]
+    except KeyError as e:
+        logging.warning(f"Log level for {env_var_name} not set: {e}")
+        return logging.WARNING
+
 
 # binary_path_python was removed in blender 2.92
 # but it is the most reliable way of getting python path for older versions
@@ -19,3 +38,5 @@
 addon_directories = tuple(map(Path, addon_utils.paths()))
 
 EXTENSIONS_REPOSITORY: Optional[str] = os.environ.get("VSCODE_EXTENSIONS_REPOSITORY", "user_default") or "user_default"
+LOG_LEVEL_GLOBAL = _parse_log("VSCODE_GLOBAL_LOG_LEVEL")
+LOG_LEVEL = _parse_log("VSCODE_LOG_LEVEL")

pythonFiles/include/blender_vscode/installation.py

@@ -6,8 +6,10 @@
 from pathlib import Path
 
 from . import handle_fatal_error
+from . import log
 from .environment import python_path
 
+LOG = log.getLogger()
 _CWD_FOR_SUBPROCESSES = python_path.parent
 
 
@@ -40,7 +42,7 @@ def ensure_package_is_installed(name: str):
 def install_package(name: str):
     target = get_package_install_directory()
     command = [str(python_path), "-m", "pip", "install", name, "--target", target]
-    print("Execute: ", " ".join(command))
+    LOG.info("Execute: ", " ".join(command))
     subprocess.run(command, cwd=_CWD_FOR_SUBPROCESSES)
 
     if not module_can_be_imported(name):
@@ -51,7 +53,7 @@ def install_pip():
     # try ensurepip before get-pip.py
     if module_can_be_imported("ensurepip"):
         command = [str(python_path), "-m", "ensurepip", "--upgrade"]
-        print("Execute: ", " ".join(command))
+        LOG.info("Execute: ", " ".join(command))
         subprocess.run(command, cwd=_CWD_FOR_SUBPROCESSES)
         return
     # pip can not necessarily be imported into Blender after this

pythonFiles/include/blender_vscode/load_addons.py

@@ -7,11 +7,13 @@
 
 import bpy
 
-from . import AddonInfo
+from . import AddonInfo, log
 from .communication import send_dict_as_json
 from .environment import addon_directories, EXTENSIONS_REPOSITORY
 from .utils import is_addon_legacy, addon_has_bl_info
 
+LOG = log.getLogger()
+
 if bpy.app.version >= (4, 2, 0):
     _EXTENSIONS_DEFAULT_DIR = Path(bpy.utils.user_resource("EXTENSIONS", path=EXTENSIONS_REPOSITORY))
 else:
@@ -37,7 +39,7 @@ def setup_addon_links(addons_to_load: List[AddonInfo]) -> List[Dict]:
         try:
             load_path = _link_addon_or_extension(addon_info)
         except PermissionError as e:
-            print(
+            LOG.error(
                 f"""ERROR: {e} 
 Path "{e.filename}" can not be removed. **Please remove it manually!** Most likely causes:
     - Path requires admin permissions to remove
@@ -81,7 +83,7 @@ def _remove_duplicate_addon_links(addon_info: AddonInfo):
     existing_addon_with_the_same_target = does_addon_link_exist(addon_info.load_dir)
     while existing_addon_with_the_same_target:
         if existing_addon_with_the_same_target:
-            print("INFO: Removing old link:", existing_addon_with_the_same_target)
+            LOG.info(f"Removing old link: {existing_addon_with_the_same_target}")
             os.remove(existing_addon_with_the_same_target)
         existing_addon_with_the_same_target = does_addon_link_exist(addon_info.load_dir)
 
@@ -90,7 +92,7 @@ def _remove_duplicate_extension_links(addon_info: AddonInfo):
     existing_extension_with_the_same_target = does_extension_link_exist(addon_info.load_dir)
     while existing_extension_with_the_same_target:
         if existing_extension_with_the_same_target:
-            print("INFO: Removing old link:", existing_extension_with_the_same_target)
+            LOG.info(f"Removing old link: {existing_extension_with_the_same_target}")
             os.remove(existing_extension_with_the_same_target)
         existing_extension_with_the_same_target = does_extension_link_exist(addon_info.load_dir)
 
@@ -126,14 +128,14 @@ def _resolve_link(path: Path) -> Optional[str]:
             # OSError: [Errno 22] Invalid argument: '/snap/blender/5088/4.2/extensions/system/readme.txt'
             if e.errno == 22:
                 return None
-        print("Warning: can not resolve link target", e)
+        LOG.warning("can not resolve link target", e)
         return None
     except ValueError as e:
         # there are major differences in python windows junction support (3.7.0 and 3.7.9 give different errors)
         if sys.platform == "win32":
             return _resolve_link_windows_cmd(path)
         else:
-            print("Warning: can not resolve link target", e)
+            LOG.warning("can not resolve link target", e)
             return None
 
 
@@ -172,7 +174,7 @@ def ensure_extension_repo_exists(extensions_repository: str):
         repo: bpy.types.UserExtensionRepo
         if repo.module == extensions_repository:
             return repo
-    print(f'DEBUG: new extensions repository "{extensions_repository}" created')
+    LOG.debug(f'New extensions repository "{extensions_repository}" created')
     return bpy.context.preferences.extensions.repos.new(name=extensions_repository, module=extensions_repository)
 
 
@@ -183,7 +185,7 @@ def remove_broken_addon_links():
             continue
         target = _resolve_link(addon_dir)
         if target and not os.path.exists(target):
-            print("INFO: Removing invalid link:", addon_dir, "->", target)
+            LOG.info(f"Removing invalid link: {addon_dir} -> {target}")
             os.remove(addon_dir)
 
 
@@ -199,7 +201,7 @@ def remove_broken_extension_links():
             existing_extension_dir = repo_dir / file
             target = _resolve_link(existing_extension_dir)
             if target and not os.path.exists(target):
-                print("INFO: Removing invalid link:", existing_extension_dir, "->", target)
+                LOG.info(f"Removing invalid link: {existing_extension_dir} -> {target}")
                 os.remove(existing_extension_dir)
 
 

pythonFiles/include/blender_vscode/log.py

@@ -0,0 +1,56 @@
+import logging
+
+import flask.app
+
+from .environment import LOG_LEVEL, LOG_LEVEL_GLOBAL
+
+
+class ColoredFormatter(logging.Formatter):
+    white = "\x1b[1;37;20m"
+    grey = "\x1b[1;38;20m"
+    yellow = "\x1b[1;33;20m"
+    red = "\x1b[1;31;20m"
+    bold_red = "\x1b[1;31;1m"
+    reset = "\x1b[1;0m"
+    format = "%(levelname)s: %(message)s (%(filename)s:%(lineno)d)"
+
+    FORMATS = {
+        logging.DEBUG: grey + format + reset,
+        logging.INFO: white + format + reset,
+        logging.WARNING: yellow + format + reset,
+        logging.ERROR: red + format + reset,
+        logging.CRITICAL: bold_red + format + reset,
+    }
+
+    def format(self, record):
+        log_fmt = self.FORMATS.get(record.levelno)
+        formatter = logging.Formatter(log_fmt)
+        return formatter.format(record)
+
+
+def configure_flask_log(app: flask.app.Flask):
+    if LOG_LEVEL_GLOBAL <= logging.DEBUG:
+        return
+    logging.getLogger("werkzeug").disabled = True
+    app.logger.disabled = True
+
+
+def getLogger(name: str = "blender_vs"):
+    logging.getLogger().setLevel(LOG_LEVEL_GLOBAL)
+
+    log = logging.getLogger(name)
+    if log.handlers:
+        # log is already configured
+        return log
+    log.propagate = False
+    log.setLevel(LOG_LEVEL)
+
+    # create console handler with a higher log level
+    ch = logging.StreamHandler()
+    ch.setLevel(logging.DEBUG)
+
+    ch.setFormatter(ColoredFormatter())
+
+    log.addHandler(ch)
+
+    return log

pythonFiles/include/blender_vscode/operators/script_runner.py

@@ -4,6 +4,9 @@
 from bpy.props import *
 from ..utils import redraw_all
 from ..communication import register_post_action
+from .. import log
+
+LOG = log.getLogger()
 
 
 class RunScriptOperator(bpy.types.Operator):
@@ -14,6 +17,8 @@ class RunScriptOperator(bpy.types.Operator):
 
     def execute(self, context):
         ctx = prepare_script_context(self.filepath)
+        LOG.info(f'Run script: "{self.filepath}"')
+        LOG.debug(f"Run script context override: {ctx}")
         runpy.run_path(self.filepath, init_globals={"CTX": ctx})
         redraw_all()
         return {"FINISHED"}