Logging refactoring (#4891)

* move logging call into modules where actual logging is happening
don't change settings of root logging
initialize handlers when it becomes possible
add colors to logs

* rename logging module to sv_logging to avoid to confuse it with the build-in module

* add separate logger for test logs

* it's not always possible to have relative path

* during registration of extension Blender text can be None

__init__.py

@@ -117,6 +117,7 @@ def import_sverchok():
 def register():
     from sverchok.utils import ascii_print
     core.sv_register_modules(imported_modules)
+    core.enable_logging()
     core.sv_register_modules(core.imported_utils_modules())
     core.sv_register_modules(node_modules)
     ascii_print.show_welcome()
@@ -126,5 +127,6 @@ def unregister():
     core.sv_unregister_modules(imported_modules)
     core.sv_unregister_modules(core.imported_utils_modules())
     core.sv_unregister_modules(node_modules)
+    core.disable_logging()
 
 # EOF

core/__init__.py

@@ -1,6 +1,10 @@
 import importlib
+import logging
 import sys
-
+import sverchok
+import bpy
+from sverchok.utils.development import get_version_string
+from sverchok.utils.sv_logging import add_file_handler, remove_console_handler
 
 root_modules = [
     "dependencies",
@@ -84,6 +88,13 @@ def import_settings(imported_modules):
     imported_modules.append(settings)
 
 
+def import_logging(imported_modules):
+    """Should be registered second after add-on settings"""
+    module = importlib.import_module(".sv_logging", "sverchok.utils")
+    # the module will be in imported_utils_modules - move sv_logging to core?
+    # imported_modules.append(module)
+
+
 def import_all_modules(imported_modules, mods_bases):
     for mods, base in mods_bases:
         import_modules(mods, base, imported_modules)
@@ -113,10 +124,41 @@ def init_architecture():
     # print('sv: import settings')
     import_settings(imported_modules)
     # print('sv: import all modules')
+    import_logging(imported_modules)
     import_all_modules(imported_modules, mods_bases)
     return imported_modules
 
 
+def enable_logging():
+    """Should be called after registration the add-on settings.
+    Adds additional handlers according the add-on settings and set logging level"""
+    if sverchok.reload_event:
+        return
+
+    addon = bpy.context.preferences.addons.get(sverchok.__name__)
+    prefs = addon.preferences
+
+    sv_logger = logging.getLogger('sverchok')
+    level = getattr(logging, prefs.log_level)
+    sv_logger.setLevel(level)
+    if prefs.log_to_file:
+        add_file_handler(prefs.log_file_name)
+    if not prefs.log_to_console:
+        remove_console_handler()
+
+    logging.captureWarnings(True)
+    sv_logger.info(f'Initializing Sverchok logging (level={prefs.log_level}). '
+                   f'Blender version={bpy.app.version_string},'
+                   f' Sverchok version={get_version_string()}')
+
+
+def disable_logging():
+    sv_logger = logging.getLogger('sverchok')
+    for handler in sv_logger.handlers[:]:
+        handler.close()
+        sv_logger.removeHandler(handler)
+
+
 def interupted_activation_detected():
     activation_message = """\n
     ** Sverchok needs a couple of seconds to become activated when you enable it for the first time. **

core/handlers.py

@@ -1,16 +1,16 @@
 import bpy
 from bpy.app.handlers import persistent
 
+import sverchok
 from sverchok import old_nodes
 from sverchok import data_structure
 import sverchok.core.events as ev
 import sverchok.core.tasks as ts
-import sverchok.utils.logging as log
 from sverchok.core.event_system import handle_event
 from sverchok.core.socket_data import clear_all_socket_cache
 from sverchok.ui import bgl_callback_nodeview, bgl_callback_3dview
 from sverchok.utils.handle_blender_data import BlTrees
-from sverchok.utils.logging import catch_log_error, debug
+from sverchok.utils.sv_logging import catch_log_error, TextBufferHandler, sv_logger
 import sverchok.settings as settings
 
 _state = {'frame': None}
@@ -59,7 +59,7 @@ def sv_handler_undo_post(scene):
         num_to_test_against += len(ng.nodes)
 
     if undo_handler_node_count['sv_groups'] != num_to_test_against:
-        debug('looks like a node was removed, cleaning')
+        sv_logger.debug('looks like a node was removed, cleaning')
         sv_clean(scene)
 
     undo_handler_node_count['sv_groups'] = 0
@@ -154,6 +154,7 @@ def sv_post_load(scene):
     post_load handler is also called when Blender is first ran
     The method should initialize Sverchok parts which are required by loaded tree
     """
+    TextBufferHandler.add_to_main_logger()
     from sverchok import node_tree, settings
 
     # ensure current nodeview view scale / location parameters reflect users' system settings
@@ -197,7 +198,12 @@ def update_frame_change_mode():
 
 @persistent
 def save_pre_handler(scene):
-    log.clear_internal_buffer()
+    addon = bpy.context.preferences.addons.get(sverchok.__name__)
+    prefs = addon.preferences
+    if prefs.log_to_buffer_clean:
+        for handler in sv_logger.handlers:
+            if hasattr(handler, 'clear'):
+                handler.clear()
 
 
 handler_dict = {

core/socket_data.py

@@ -17,19 +17,19 @@
 # ##### END GPL LICENSE BLOCK #####
 
 """For internal usage of the sockets module"""
-
+import logging
 from collections import UserDict
 from itertools import chain
 from traceback import format_list, extract_stack
 from typing import NewType, Optional, Literal
 
 from bpy.types import NodeSocket
 from sverchok.core.sv_custom_exceptions import SvNoDataError
-from sverchok.utils.logging import debug
 from sverchok.utils.handle_blender_data import BlTrees
 
 
 SockId = NewType('SockId', str)
+sv_logger = logging.getLogger('sverchok')
 
 
 class DebugMemory(UserDict):
@@ -112,7 +112,7 @@ def _update_sockets(self):
                         continue
                     if sock.socket_id in self._id_sock:
                         ds = self._id_sock[sock.socket_id]
-                        debug(f"SOCKET ID DUPLICATION: "
+                        sv_logger.debug(f"SOCKET ID DUPLICATION: "
                               f"1 - {ds.id_data.name} {ds.node.name=} {ds.name=}"
                               f"2 - {sock.id_data.name} {node.name=} {sock.name=}")
                     self._id_sock[sock.socket_id] = sock

core/sockets.py

@@ -46,7 +46,6 @@
 from sverchok.utils.curve.algorithms import reparametrize_curve
 from sverchok.utils.surface import SvSurface
 
-from sverchok.utils.logging import warning
 from sverchok.dependencies import FreeCAD
 
 STANDARD_TYPES = SIMPLE_DATA_TYPES + (SvCurve, SvSurface)

core/tasks.py

@@ -6,7 +6,7 @@
 import bpy
 from sverchok.data_structure import post_load_call
 from sverchok.core.sv_custom_exceptions import CancelError
-from sverchok.utils.logging import catch_log_error, debug
+from sverchok.utils.sv_logging import catch_log_error, sv_logger
 from sverchok.utils.profile import profile
 from sverchok.utils.handle_blender_data import BlTrees
 
@@ -119,7 +119,7 @@ def _finish(self):
             t['SKIP_UPDATE'] = True
 
         gc.enable()
-        debug(f'Global update - {int((time() - self._start_time) * 1000)}ms')
+        sv_logger.debug(f'Global update - {int((time() - self._start_time) * 1000)}ms')
         del self._start_time
 
     @cached_property
@@ -143,7 +143,7 @@ def _main_area(self) -> Optional:
                         return area
                 except ReferenceError:
                     # probably all reports should be cleaned through search
-                    debug(f"Unable report a nodes updating progress")
+                    sv_logger.debug(f"Unable report a nodes updating progress")
 
     def _report_progress(self, text: str = None):
         """Show text in the tree editor header. If text is none the header

core/update_system.py

@@ -12,7 +12,7 @@
 from sverchok.core.sv_custom_exceptions import CancelError, SvNoDataError
 from sverchok.core.socket_conversions import conversions
 from sverchok.utils.profile import profile
-from sverchok.utils.logging import log_error
+from sverchok.utils.sv_logging import node_error_logger
 from sverchok.utils.tree_walk import bfs_walk
 
 if TYPE_CHECKING:
@@ -699,7 +699,7 @@ def __exit__(self, exc_type, exc_val, exc_tb):
             self._node[ERROR_KEY] = None
             self._node[TIME_KEY] = perf_counter() - self._start
         else:
-            log_error(exc_val)
+            node_error_logger.error(exc_val, exc_info=True)
             self._node[UPDATE_KEY] = False
             self._node[ERROR_KEY] = repr(exc_val)
 

data_structure.py

@@ -36,7 +36,7 @@
     tile as np_tile,
     float64,
     int32, int64)
-from sverchok.utils.logging import debug
+from sverchok.utils.sv_logging import sv_logger
 import numpy as np
 
 
@@ -1255,7 +1255,7 @@ def changable_sockets(node, inputsocketname, outputsocketname):
     if not inputsocketname in node.inputs:
         # - node not initialized in sv_init yet,
         # - or socketname incorrect
-        debug(f"changable_socket was called on {node.name} with a socket named {inputsocketname}, this socket does not exist")
+        sv_logger.debug(f"changable_socket was called on {node.name} with a socket named {inputsocketname}, this socket does not exist")
         return
 
     in_socket = node.inputs[inputsocketname]

dependencies.py

@@ -23,11 +23,14 @@
 
 todo: Create dependencies.txt file and import modules from there
 """
+import logging
 
-from sverchok.utils.logging import info, debug
 import sverchok.settings as settings
 
 
+logger = logging.getLogger('sverchok')
+
+
 class SvDependency():
     """
     Definition of external dependency package.
@@ -186,6 +189,6 @@ def register():
     good_names = [d.package for d in sv_dependencies.values()
                   if d.module is not None and d.package is not None]
     if good_names:
-        info("Dependencies available: %s.", ", ".join(good_names))
+        logger.info("Dependencies available: %s.", ", ".join(good_names))
     else:
-        info("No dependencies are available.")
+        logger.info("No dependencies are available.")

node_scripts/SNLite_templates/demo/turtle_random_walk.py

@@ -9,14 +9,15 @@
 out  out_face_mask   s
 out  out_face_data s
 """
-
+import logging
 import random
 
 from sverchok.data_structure import zip_long_repeat
 from sverchok.utils.sv_bmesh_utils import bmesh_from_pydata
-from sverchok.utils.logging import debug, info
 from sverchok.utils.turtle import Turtle
 
+logger = logging.getLogger('sverchok')
+
 if in_select_mask is None:
     in_select_mask = [[]]
 if in_paint_mask is None:
@@ -27,7 +28,7 @@
 objects = zip_long_repeat(in_verts, in_faces, in_start_face_idx, in_steps,
             in_select_mask, in_paint_mask, in_seed)
 for verts, faces, start_face, steps, select_mask, paint_mask, seed in objects:
-    info(seed)
+    logger.info(seed)
     if isinstance(seed, (list, tuple)):
         seed = seed[0]
     random.seed(seed)

node_scripts/SNLite_templates/demo/turtle_spiral.py

@@ -8,18 +8,20 @@
 out  out_face_mask s
 out  out_face_data s
 """
+import logging
 
 from sverchok.data_structure import zip_long_repeat
 from sverchok.utils.sv_bmesh_utils import bmesh_from_pydata
-from sverchok.utils.logging import info, debug
 from sverchok.utils.turtle import Turtle
 
+logger = logging.getLogger('sverchok')
+
 if in_select_mask is None:
     in_select_mask = [[]]
 if in_paint_mask is None:
     in_paint_mask = [[]]
 
-info(in_start_face_idx)
+logger.info(in_start_face_idx)
 
 out_face_mask = []
 out_face_data = []
@@ -54,7 +56,7 @@
 
     for i in range(turns * 2):
         steps = (i+1)*2
-        debug("Steps := %s", steps)
+        logger.debug("Steps := %s", steps)
         turtle.step(steps)
         turtle.turn_prev()
         turtle.step(steps)

node_scripts/SNLite_templates/demo/voronoi_scipy_3d.py

@@ -3,18 +3,15 @@
 out out_verts v
 out out_faces s
 """
+import logging
 
-import numpy as np
-import sys
-
-from sverchok.utils.logging import exception, info
-from sverchok.data_structure import zip_long_repeat
+logger = logging.getLogger('sverchok')
 
 try:
     import scipy
     from scipy.spatial import Voronoi
 except ImportError as e:
-    info("SciPy module is not available. Please refer to https://github.com/nortikin/sverchok/wiki/Non-standard-Python-modules-installation for how to install it.")
+    logger.info("SciPy module is not available. Please refer to https://github.com/nortikin/sverchok/wiki/Non-standard-Python-modules-installation for how to install it.")
     raise e
 
 out_verts = []

node_scripts/SNLite_templates/utils/spherical_voronoi_3d_scipy.py

@@ -5,19 +5,21 @@
 out out_verts v
 out out_faces s
 """
+import logging
 
 import numpy as np
 import sys
 
-from sverchok.utils.logging import exception, info
 from sverchok.data_structure import zip_long_repeat
 from sverchok.utils.math import to_spherical, from_spherical
 
+logger = logging.getLogger('sverchok')
+
 try:
     import scipy
     from scipy.spatial import SphericalVoronoi
 except ImportError as e:
-    info("SciPy module is not available. Please refer to https://github.com/nortikin/sverchok/wiki/Non-standard-Python-modules-installation for how to install it.")
+    logger.info("SciPy module is not available. Please refer to https://github.com/nortikin/sverchok/wiki/Non-standard-Python-modules-installation for how to install it.")
     raise e
 
 def to_radius(r, v, c):
@@ -36,7 +38,7 @@ def to_radius(r, v, c):
     if isinstance(radius, (list, tuple)):
         radius = radius[0]
     center = center[0]
-    #info("Center: %s, radius: %s", center, radius)
+    # logger.info("Center: %s, radius: %s", center, radius)
     points = np.array([to_radius(radius, v, center) for v in points])
 
     vor = SphericalVoronoi(points, radius=radius, center=np.array(center))