Update Files and Fixes

core/mmd/core/bone.py

@@ -15,14 +15,14 @@ from bpy.types import Object, EditBone, PoseBone, Constraint, Armature, BoneColl
 from .. import bpyutils
 from ..bpyutils import TransformConstraintOp
 from ..utils import ItemOp
-from ....logging_setup import logger
+from ....core.logging_setup import logger
 
 if TYPE_CHECKING:
     from ..properties.root import MMDRoot, MMDDisplayItemFrame
     from ..properties.pose_bone import MMDBone
 
 
-def remove_constraint(constraints: bpy.types.ConstraintSequence, name: str) -> bool:
+def remove_constraint(constraints: Any, name: str) -> bool:
     """Remove a constraint by name if it exists"""
     c = constraints.get(name, None)
     if c:
@@ -30,7 +30,6 @@ def remove_constraint(constraints: bpy.types.ConstraintSequence, name: str) -> b
         return True
     return False
 
-
 def remove_edit_bones(edit_bones: bpy.types.ArmatureEditBones, bone_names: List[str]) -> None:
     """Remove edit bones by name"""
     for name in bone_names:
@@ -573,7 +572,7 @@ class _AT_ShadowBoneRemove:
         remove_edit_bones(edit_bones, self.__shadow_bone_names)
         logger.debug(f"Removed shadow bones: {self.__shadow_bone_names}")
 
-    def update_pose_bones(self, pose_bones: bpy.types.ArmaturePoseBones) -> None:
+    def update_pose_bones(self, pose_bones: Any) -> None:
         """Update pose bones (no-op for removal)"""
         pass
 
@@ -628,7 +627,7 @@ class _AT_ShadowBoneCreate:
         shadow.roll = bone.roll
         logger.debug(f"Created/updated shadow bone: {shadow_bone_name}")
 
-    def update_pose_bones(self, pose_bones: bpy.types.ArmaturePoseBones) -> None:
+    def update_pose_bones(self, pose_bones: Any) -> None:
         """Update pose bones by setting up shadow bone properties"""
         if self.__shadow_bone_name not in pose_bones:
             logger.debug(f"Shadow bone {self.__shadow_bone_name} not found, using target bone directly")

core/mmd/core/camera.py

@@ -13,7 +13,7 @@ from bpy.types import Object, ID, Camera, Context
 from mathutils import Vector, Matrix, Euler
 
 from ..bpyutils import FnContext, Props
-from core.logging_setup import logger
+from ....core.logging_setup import logger
 
 class FnCamera:
     @staticmethod

core/mmd/core/lamp.py

@@ -6,36 +6,48 @@
 # MMD Tools is licensed under the terms of the GNU General Public License version 3 (GPLv3) same as Avatar Toolkit.
 
 import bpy
+from typing import Optional, Union, Any, List, Tuple
+from bpy.types import Object, Context
 
 from ..bpyutils import FnContext, Props
+from ....core.logging_setup import logger
 
 
 class MMDLamp:
-    def __init__(self, obj):
+    def __init__(self, obj: Object) -> None:
         if MMDLamp.isLamp(obj):
             obj = obj.parent
         if obj and obj.type == "EMPTY" and obj.mmd_type == "LIGHT":
-            self.__emptyObj = obj
+            self.__emptyObj: Object = obj
         else:
-            raise ValueError("%s is not MMDLamp" % str(obj))
+            error_msg = f"{str(obj)} is not MMDLamp"
+            logger.error(error_msg)
+            raise ValueError(error_msg)
 
     @staticmethod
-    def isLamp(obj):
+    def isLamp(obj: Optional[Object]) -> bool:
-        return obj and obj.type in {"LIGHT", "LAMP"}
+        """Check if the object is a lamp/light object"""
+        return obj is not None and obj.type in {"LIGHT", "LAMP"}
 
     @staticmethod
-    def isMMDLamp(obj):
+    def isMMDLamp(obj: Optional[Object]) -> bool:
+        """Check if the object is an MMD lamp"""
         if MMDLamp.isLamp(obj):
             obj = obj.parent
-        return obj and obj.type == "EMPTY" and obj.mmd_type == "LIGHT"
+        return obj is not None and obj.type == "EMPTY" and obj.mmd_type == "LIGHT"
 
     @staticmethod
-    def convertToMMDLamp(lampObj, scale=1.0):
+    def convertToMMDLamp(lampObj: Object, scale: float = 1.0) -> 'MMDLamp':
+        """Convert a regular lamp to an MMD lamp"""
         if MMDLamp.isMMDLamp(lampObj):
+            logger.debug(f"Object {lampObj.name} is already an MMD lamp")
             return MMDLamp(lampObj)
 
-        empty = bpy.data.objects.new(name="MMD_Light", object_data=None)
+        logger.info(f"Converting {lampObj.name} to MMD lamp with scale {scale}")
-        FnContext.link_object(FnContext.ensure_context(), empty)
+        
+        empty: Object = bpy.data.objects.new(name="MMD_Light", object_data=None)
+        context = FnContext.ensure_context()
+        FnContext.link_object(context, empty)
 
         empty.rotation_mode = "XYZ"
         empty.lock_rotation = (True, True, True)
@@ -57,13 +69,18 @@ class MMDLamp:
         constraint.track_axis = "TRACK_NEGATIVE_Z"
         constraint.up_axis = "UP_Y"
 
+        logger.debug(f"Successfully created MMD lamp from {lampObj.name}")
         return MMDLamp(empty)
 
-    def object(self):
+    def object(self) -> Object:
+        """Get the empty object that represents this MMD lamp"""
         return self.__emptyObj
 
-    def lamp(self):
+    def lamp(self) -> Object:
+        """Get the actual lamp/light object"""
         for i in self.__emptyObj.children:
             if MMDLamp.isLamp(i):
                 return i
-        raise KeyError
+        error_msg = f"No lamp found in MMD lamp {self.__emptyObj.name}"
+        logger.error(error_msg)
+        raise KeyError(error_msg)

core/mmd/core/material.py

@@ -7,7 +7,7 @@
 
 import logging
 import os
-from typing import TYPE_CHECKING, Callable, Iterable, Optional, Tuple, cast
+from typing import TYPE_CHECKING, Callable, Iterable, Optional, Tuple, cast, Dict, List, Any, Union, Set
 
 import bpy
 from mathutils import Vector
@@ -15,6 +15,7 @@ from mathutils import Vector
 from ..bpyutils import FnContext
 from .exceptions import MaterialNotFoundError
 from .shader import _NodeGroupUtils
+from ....core.logging_setup import logger
 
 if TYPE_CHECKING:
     from ..properties.material import MMDMaterial
@@ -27,48 +28,53 @@ SPHERE_MODE_SUBTEX = 3
 
 
 class _DummyTexture:
-    def __init__(self, image):
+    def __init__(self, image: bpy.types.Image):
-        self.type = "IMAGE"
+        self.type: str = "IMAGE"
-        self.image = image
+        self.image: bpy.types.Image = image
-        self.use_mipmap = True
+        self.use_mipmap: bool = True
 
 
 class _DummyTextureSlot:
-    def __init__(self, image):
+    def __init__(self, image: bpy.types.Image):
-        self.diffuse_color_factor = 1
+        self.diffuse_color_factor: float = 1
-        self.uv_layer = ""
+        self.uv_layer: str = ""
-        self.texture = _DummyTexture(image)
+        self.texture: _DummyTexture = _DummyTexture(image)
 
 
 class FnMaterial:
     __NODES_ARE_READONLY: bool = False
 
     def __init__(self, material: bpy.types.Material):
-        self.__material = material
+        self.__material: bpy.types.Material = material
-        self._nodes_are_readonly = FnMaterial.__NODES_ARE_READONLY
+        self._nodes_are_readonly: bool = FnMaterial.__NODES_ARE_READONLY
 
     @staticmethod
-    def set_nodes_are_readonly(nodes_are_readonly: bool):
+    def set_nodes_are_readonly(nodes_are_readonly: bool) -> None:
         FnMaterial.__NODES_ARE_READONLY = nodes_are_readonly
 
     @classmethod
-    def from_material_id(cls, material_id: str):
+    def from_material_id(cls, material_id: str) -> Optional['FnMaterial']:
         for material in bpy.data.materials:
             if material.mmd_material.material_id == material_id:
                 return cls(material)
         return None
 
     @staticmethod
-    def clean_materials(obj, can_remove: Callable[[bpy.types.Material], bool]):
+    def clean_materials(obj: bpy.types.Object, can_remove: Callable[[bpy.types.Material], bool]) -> None:
         materials = obj.data.materials
         materials_pop = materials.pop
+        removed_count = 0
         for i in sorted((x for x, m in enumerate(materials) if can_remove(m)), reverse=True):
             m = materials_pop(index=i)
+            removed_count += 1
             if m.users < 1:
                 bpy.data.materials.remove(m)
         
+        if removed_count > 0:
+            logger.debug(f"Removed {removed_count} materials from {obj.name}")
+
     @staticmethod
-    def swap_materials(mesh_object: bpy.types.Object, mat1_ref: str | int, mat2_ref: str | int, reverse=False, swap_slots=False) -> Tuple[bpy.types.Material, bpy.types.Material]:
+    def swap_materials(mesh_object: bpy.types.Object, mat1_ref: Union[str, int], mat2_ref: Union[str, int], reverse: bool = False, swap_slots: bool = False) -> Tuple[bpy.types.Material, bpy.types.Material]:
         """
         This method will assign the polygons of mat1 to mat2.
         If reverse is True it will also swap the polygons assigned to mat2 to mat1.
@@ -98,8 +104,12 @@ class FnMaterial:
         except (KeyError, IndexError) as exc:
             # Wrap exceptions within our custom ones
             raise MaterialNotFoundError() from exc
+        
         mat1_idx = mesh.materials.find(mat1.name)
         mat2_idx = mesh.materials.find(mat2.name)
+        
+        logger.debug(f"Swapping materials: {mat1.name} (idx:{mat1_idx}) <-> {mat2.name} (idx:{mat2_idx}) in {mesh_object.name}")
+        
         # Swap polygons
         for poly in mesh.polygons:
             if poly.material_index == mat1_idx:
@@ -113,33 +123,37 @@ class FnMaterial:
         return mat1, mat2
 
     @staticmethod
-    def fixMaterialOrder(meshObj: bpy.types.Object, material_names: Iterable[str]):
+    def fixMaterialOrder(meshObj: bpy.types.Object, material_names: Iterable[str]) -> None:
         """
         This method will fix the material order. Which is lost after joining meshes.
         """
         materials = cast(bpy.types.Mesh, meshObj.data).materials
+        logger.debug(f"Fixing material order for {meshObj.name}")
+        
         for new_idx, mat in enumerate(material_names):
             # Get the material that is currently on this index
             other_mat = materials[new_idx]
             if other_mat.name == mat:
                 continue  # This is already in place
+            logger.debug(f"Moving material {mat} to index {new_idx}")
             FnMaterial.swap_materials(meshObj, mat, new_idx, reverse=True, swap_slots=True)
 
     @property
-    def material_id(self):
+    def material_id(self) -> int:
-        mmd_mat: MMDMaterial = self.__material.mmd_material
+        mmd_mat: 'MMDMaterial' = self.__material.mmd_material
         if mmd_mat.material_id < 0:
             max_id = -1
             for mat in bpy.data.materials:
                 max_id = max(max_id, mat.mmd_material.material_id)
             mmd_mat.material_id = max_id + 1
+            logger.debug(f"Assigned new material ID {mmd_mat.material_id} to {self.__material.name}")
         return mmd_mat.material_id
 
     @property
-    def material(self):
+    def material(self) -> bpy.types.Material:
         return self.__material
 
-    def __same_image_file(self, image, filepath):
+    def __same_image_file(self, image: Optional[bpy.types.Image], filepath: str) -> bool:
         if image and image.source == "FILE":
             # pylint: disable=assignment-from-no-return
             img_filepath = bpy.path.abspath(image.filepath)  # image.filepath_from_user()
@@ -152,14 +166,15 @@ class FnMaterial:
                 pass
         return False
 
-    def _load_image(self, filepath):
+    def _load_image(self, filepath: str) -> bpy.types.Image:
         img = next((i for i in bpy.data.images if self.__same_image_file(i, filepath)), None)
         if img is None:
             # pylint: disable=bare-except
             try:
+                logger.debug(f"Loading image: {filepath}")
                 img = bpy.data.images.load(filepath)
             except:
-                logging.warning("Cannot create a texture for %s. No such file.", filepath)
+                logger.warning(f"Cannot create a texture for {filepath}. No such file.")
                 img = bpy.data.images.new(os.path.basename(filepath), 1, 1)
                 img.source = "FILE"
                 img.filepath = filepath
@@ -170,43 +185,46 @@ class FnMaterial:
                 img.alpha_mode = "NONE"
         return img
 
-    def update_toon_texture(self):
+    def update_toon_texture(self) -> None:
         if self._nodes_are_readonly:
             return
-        mmd_mat: MMDMaterial = self.__material.mmd_material
+        mmd_mat: 'MMDMaterial' = self.__material.mmd_material
         if mmd_mat.is_shared_toon_texture:
             shared_toon_folder = FnContext.get_addon_preferences_attribute(FnContext.ensure_context(), "shared_toon_folder", "")
             toon_path = os.path.join(shared_toon_folder, "toon%02d.bmp" % (mmd_mat.shared_toon_texture + 1))
+            logger.debug(f"Using shared toon texture: {toon_path}")
             self.create_toon_texture(bpy.path.resolve_ncase(path=toon_path))
         elif mmd_mat.toon_texture != "":
+            logger.debug(f"Using custom toon texture: {mmd_mat.toon_texture}")
             self.create_toon_texture(mmd_mat.toon_texture)
         else:
+            logger.debug(f"Removing toon texture from {self.__material.name}")
             self.remove_toon_texture()
 
-    def _mix_diffuse_and_ambient(self, mmd_mat):
+    def _mix_diffuse_and_ambient(self, mmd_mat: 'MMDMaterial') -> List[float]:
         r, g, b = mmd_mat.diffuse_color
         ar, ag, ab = mmd_mat.ambient_color
         return [min(1.0, 0.5 * r + ar), min(1.0, 0.5 * g + ag), min(1.0, 0.5 * b + ab)]
 
-    def update_drop_shadow(self):
+    def update_drop_shadow(self) -> None:
         pass
 
-    def update_enabled_toon_edge(self):
+    def update_enabled_toon_edge(self) -> None:
         if self._nodes_are_readonly:
             return
         self.update_edge_color()
 
-    def update_edge_color(self):
+    def update_edge_color(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.__material
-        mmd_mat: MMDMaterial = mat.mmd_material
+        mmd_mat: 'MMDMaterial' = mat.mmd_material
         color, alpha = mmd_mat.edge_color[:3], mmd_mat.edge_color[3]
         line_color = color + (min(alpha, int(mmd_mat.enabled_toon_edge)),)
         if hasattr(mat, "line_color"):  # freestyle line color
             mat.line_color = line_color
 
-        mat_edge: bpy.types.Material = bpy.data.materials.get("mmd_edge." + mat.name, None)
+        mat_edge: Optional[bpy.types.Material] = bpy.data.materials.get("mmd_edge." + mat.name, None)
         if mat_edge:
             mat_edge.mmd_material.edge_color = line_color
 
@@ -218,38 +236,45 @@ class FnMaterial:
             if node_shader and "Alpha" in node_shader.inputs:
                 node_shader.inputs["Alpha"].default_value = alpha
         
-    def update_edge_weight(self):
+        logger.debug(f"Updated edge color for {mat.name}")
+
+    def update_edge_weight(self) -> None:
         pass
 
-    def get_texture(self):
+    def get_texture(self) -> Optional[_DummyTexture]:
         return self.__get_texture_node("mmd_base_tex", use_dummy=True)
 
-    def create_texture(self, filepath):
+    def create_texture(self, filepath: str) -> _DummyTextureSlot:
         texture = self.__create_texture_node("mmd_base_tex", filepath, (-4, -1))
+        logger.debug(f"Created base texture for {self.__material.name}: {filepath}")
         return _DummyTextureSlot(texture.image)
 
-    def remove_texture(self):
+    def remove_texture(self) -> None:
         if self._nodes_are_readonly:
             return
+        logger.debug(f"Removing base texture from {self.__material.name}")
         self.__remove_texture_node("mmd_base_tex")
 
-    def get_sphere_texture(self):
+    def get_sphere_texture(self) -> Optional[_DummyTexture]:
         return self.__get_texture_node("mmd_sphere_tex", use_dummy=True)
 
-    def use_sphere_texture(self, use_sphere, obj=None):
+    def use_sphere_texture(self, use_sphere: bool, obj: Optional[bpy.types.Object] = None) -> None:
         if self._nodes_are_readonly:
             return
         if use_sphere:
+            logger.debug(f"Enabling sphere texture for {self.__material.name}")
             self.update_sphere_texture_type(obj)
         else:
+            logger.debug(f"Disabling sphere texture for {self.__material.name}")
             self.__update_shader_input("Sphere Tex Fac", 0)
 
-    def create_sphere_texture(self, filepath, obj=None):
+    def create_sphere_texture(self, filepath: str, obj: Optional[bpy.types.Object] = None) -> _DummyTextureSlot:
         texture = self.__create_texture_node("mmd_sphere_tex", filepath, (-2, -2))
+        logger.debug(f"Created sphere texture for {self.__material.name}: {filepath}")
         self.update_sphere_texture_type(obj)
         return _DummyTextureSlot(texture.image)
 
-    def update_sphere_texture_type(self, obj=None):
+    def update_sphere_texture_type(self, obj: Optional[bpy.types.Object] = None) -> None:
         if self._nodes_are_readonly:
             return
         sphere_texture_type = int(self.material.mmd_material.sphere_texture_type)
@@ -277,48 +302,54 @@ class FnMaterial:
                         next(uv_layers, None)  # skip base UV
                         subtex_uv = getattr(next(uv_layers, None), "name", "")
                         if subtex_uv != "UV1":
-                            logging.info(' * material(%s): object "%s" use UV "%s" for SubTex', mat.name, obj.name, subtex_uv)
+                            logger.info(f'Material({mat.name}): object "{obj.name}" use UV "{subtex_uv}" for SubTex')
                     links.new(nodes["mmd_tex_uv"].outputs["SubTex UV"], texture.inputs["Vector"])
                 else:
                     links.new(nodes["mmd_tex_uv"].outputs["Sphere UV"], texture.inputs["Vector"])
         
-    def remove_sphere_texture(self):
+        logger.debug(f"Updated sphere texture type for {self.material.name}: {sphere_texture_type}")
+
+    def remove_sphere_texture(self) -> None:
         if self._nodes_are_readonly:
             return
+        logger.debug(f"Removing sphere texture from {self.__material.name}")
         self.__remove_texture_node("mmd_sphere_tex")
 
-    def get_toon_texture(self):
+    def get_toon_texture(self) -> Optional[_DummyTexture]:
         return self.__get_texture_node("mmd_toon_tex", use_dummy=True)
 
-    def use_toon_texture(self, use_toon):
+    def use_toon_texture(self, use_toon: bool) -> None:
         if self._nodes_are_readonly:
             return
+        logger.debug(f"{'Enabling' if use_toon else 'Disabling'} toon texture for {self.__material.name}")
         self.__update_shader_input("Toon Tex Fac", use_toon)
 
-    def create_toon_texture(self, filepath):
+    def create_toon_texture(self, filepath: str) -> _DummyTextureSlot:
         texture = self.__create_texture_node("mmd_toon_tex", filepath, (-3, -1.5))
+        logger.debug(f"Created toon texture for {self.__material.name}: {filepath}")
         return _DummyTextureSlot(texture.image)
 
-    def remove_toon_texture(self):
+    def remove_toon_texture(self) -> None:
         if self._nodes_are_readonly:
             return
+        logger.debug(f"Removing toon texture from {self.__material.name}")
         self.__remove_texture_node("mmd_toon_tex")
 
-    def __get_texture_node(self, node_name, use_dummy=False):
+    def __get_texture_node(self, node_name: str, use_dummy: bool = False) -> Optional[Union[bpy.types.ShaderNodeTexImage, _DummyTexture]]:
         mat = self.material
         texture = getattr(mat.node_tree, "nodes", {}).get(node_name, None)
         if isinstance(texture, bpy.types.ShaderNodeTexImage):
             return _DummyTexture(texture.image) if use_dummy else texture
         return None
 
-    def __remove_texture_node(self, node_name):
+    def __remove_texture_node(self, node_name: str) -> None:
         mat = self.material
         texture = getattr(mat.node_tree, "nodes", {}).get(node_name, None)
         if isinstance(texture, bpy.types.ShaderNodeTexImage):
             mat.node_tree.nodes.remove(texture)
             mat.update_tag()
 
-    def __create_texture_node(self, node_name, filepath, pos):
+    def __create_texture_node(self, node_name: str, filepath: str, pos: Tuple[float, float]) -> bpy.types.ShaderNodeTexImage:
         texture = self.__get_texture_node(node_name)
         if texture is None:
             from mathutils import Vector
@@ -334,23 +365,25 @@ class FnMaterial:
         self.__update_shader_nodes()
         return texture
 
-    def update_ambient_color(self):
+    def update_ambient_color(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
         mmd_mat = mat.mmd_material
         mat.diffuse_color[:3] = self._mix_diffuse_and_ambient(mmd_mat)
         self.__update_shader_input("Ambient Color", mmd_mat.ambient_color[:] + (1,))
+        logger.debug(f"Updated ambient color for {mat.name}")
 
-    def update_diffuse_color(self):
+    def update_diffuse_color(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
         mmd_mat = mat.mmd_material
         mat.diffuse_color[:3] = self._mix_diffuse_and_ambient(mmd_mat)
         self.__update_shader_input("Diffuse Color", mmd_mat.diffuse_color[:] + (1,))
+        logger.debug(f"Updated diffuse color for {mat.name}")
 
-    def update_alpha(self):
+    def update_alpha(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
@@ -368,16 +401,18 @@ class FnMaterial:
             mat.diffuse_color[3] = mmd_mat.alpha
         self.__update_shader_input("Alpha", mmd_mat.alpha)
         self.update_self_shadow_map()
+        logger.debug(f"Updated alpha for {mat.name}: {mmd_mat.alpha}")
 
-    def update_specular_color(self):
+    def update_specular_color(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
         mmd_mat = mat.mmd_material
         mat.specular_color = mmd_mat.specular_color
         self.__update_shader_input("Specular Color", mmd_mat.specular_color[:] + (1,))
+        logger.debug(f"Updated specular color for {mat.name}")
 
-    def update_shininess(self):
+    def update_shininess(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
@@ -388,8 +423,9 @@ class FnMaterial:
         if hasattr(mat, "specular_hardness"):
             mat.specular_hardness = mmd_mat.shininess
         self.__update_shader_input("Reflect", mmd_mat.shininess)
+        logger.debug(f"Updated shininess for {mat.name}: {mmd_mat.shininess}")
 
-    def update_is_double_sided(self):
+    def update_is_double_sided(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
@@ -399,8 +435,9 @@ class FnMaterial:
         elif hasattr(mat, "use_backface_culling"):
             mat.use_backface_culling = not mmd_mat.is_double_sided
         self.__update_shader_input("Double Sided", mmd_mat.is_double_sided)
+        logger.debug(f"Updated double-sided setting for {mat.name}: {mmd_mat.is_double_sided}")
 
-    def update_self_shadow_map(self):
+    def update_self_shadow_map(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
@@ -408,21 +445,24 @@ class FnMaterial:
         cast_shadows = mmd_mat.enabled_self_shadow_map if mmd_mat.alpha > 1e-3 else False
         if hasattr(mat, "shadow_method"):
             mat.shadow_method = "HASHED" if cast_shadows else "NONE"
+        logger.debug(f"Updated self shadow map for {mat.name}: {cast_shadows}")
 
-    def update_self_shadow(self):
+    def update_self_shadow(self) -> None:
         if self._nodes_are_readonly:
             return
         mat = self.material
         mmd_mat = mat.mmd_material
         self.__update_shader_input("Self Shadow", mmd_mat.enabled_self_shadow)
+        logger.debug(f"Updated self shadow for {mat.name}: {mmd_mat.enabled_self_shadow}")
 
     @staticmethod
-    def convert_to_mmd_material(material, context=bpy.context):
+    def convert_to_mmd_material(material: bpy.types.Material, context: bpy.types.Context = bpy.context) -> None:
         m, mmd_material = material, material.mmd_material
+        logger.debug(f"Converting material to MMD material: {material.name}")
 
         if m.use_nodes and next((n for n in m.node_tree.nodes if n.name.startswith("mmd_")), None) is None:
 
-            def search_tex_image_node(node: bpy.types.ShaderNode):
+            def search_tex_image_node(node: bpy.types.ShaderNode) -> Optional[bpy.types.ShaderNodeTexImage]:
                 if node.type == "TEX_IMAGE":
                     return node
                 for node_input in node.inputs:
@@ -459,6 +499,7 @@ class FnMaterial:
             if tex_node is None:
                 tex_node = next((n for n in m.node_tree.nodes if n.bl_idname == "ShaderNodeTexImage"), None)
             if tex_node:
+                logger.debug(f"Found texture node for {material.name}: {tex_node.name}")
                 tex_node.name = "mmd_base_tex"
             else:
                 # Take the Base Color from BSDF if there's no texture
@@ -466,6 +507,7 @@ class FnMaterial:
                 if bsdf_node:
                     base_color_input = bsdf_node.inputs.get('Base Color') or bsdf_node.inputs.get('Color')
                     if base_color_input:
+                        logger.debug(f"Using BSDF base color for {material.name}")
                         mmd_material.diffuse_color = base_color_input.default_value[:3]
                         # ambient should be half the diffuse
                         mmd_material.ambient_color = [x * 0.5 for x in mmd_material.diffuse_color]
@@ -498,9 +540,10 @@ class FnMaterial:
         if m.use_nodes:
             nodes_to_remove = [n for n in m.node_tree.nodes if n.type == 'BSDF_PRINCIPLED' or n.type.startswith('BSDF_')]
             for n in nodes_to_remove:
+                logger.debug(f"Removing BSDF node from {material.name}: {n.name}")
                 m.node_tree.nodes.remove(n)
 
-    def __update_shader_input(self, name, val):
+    def __update_shader_input(self, name: str, val: Any) -> None:
         mat = self.material
         if mat.name.startswith("mmd_"):  # skip mmd_edge.*
             return
@@ -512,26 +555,29 @@ class FnMaterial:
                 val = min(max(val, interface_socket.min_value), interface_socket.max_value)
             shader.inputs[name].default_value = val
 
-    def __update_shader_nodes(self):
+    def __update_shader_nodes(self) -> None:
         mat = self.material
         if mat.node_tree is None:
+            logger.debug(f"Creating node tree for {mat.name}")
             mat.use_nodes = True
             mat.node_tree.nodes.clear()
 
         nodes, links = mat.node_tree.nodes, mat.node_tree.links
 
         class _Dummy:
-            default_value, is_linked = None, True
+            default_value: Any = None
+            is_linked: bool = True
 
         node_shader = nodes.get("mmd_shader", None)
         if node_shader is None:
+            logger.debug(f"Creating MMD shader node for {mat.name}")
             node_shader: bpy.types.ShaderNodeGroup = nodes.new("ShaderNodeGroup")
             node_shader.name = "mmd_shader"
             node_shader.location = (0, 1500)
             node_shader.width = 200
             node_shader.node_tree = self.__get_shader()
 
-            mmd_mat: MMDMaterial = mat.mmd_material
+            mmd_mat: 'MMDMaterial' = mat.mmd_material
             node_shader.inputs.get("Ambient Color", _Dummy).default_value = mmd_mat.ambient_color[:] + (1,)
             node_shader.inputs.get("Diffuse Color", _Dummy).default_value = mmd_mat.diffuse_color[:] + (1,)
             node_shader.inputs.get("Specular Color", _Dummy).default_value = mmd_mat.specular_color[:] + (1,)
@@ -543,6 +589,7 @@ class FnMaterial:
 
         node_uv = nodes.get("mmd_tex_uv", None)
         if node_uv is None:
+            logger.debug(f"Creating MMD UV node for {mat.name}")
             node_uv: bpy.types.ShaderNodeGroup = nodes.new("ShaderNodeGroup")
             node_uv.name = "mmd_tex_uv"
             node_uv.location = node_shader.location + Vector((-5 * 210, -2.5 * 220))
@@ -567,12 +614,13 @@ class FnMaterial:
                 if not texture.inputs["Vector"].is_linked:
                     links.new(node_uv.outputs[name_uv_out], texture.inputs["Vector"])
 
-    def __get_shader_uv(self):
+    def __get_shader_uv(self) -> bpy.types.ShaderNodeTree:
         group_name = "MMDTexUV"
         shader: bpy.types.ShaderNodeTree = bpy.data.node_groups.get(group_name, None) or bpy.data.node_groups.new(name=group_name, type="ShaderNodeTree")
         if len(shader.nodes):
             return shader
 
+        logger.debug(f"Creating MMD UV shader node group")
         ng = _NodeGroupUtils(shader)
 
         ############################################################################
@@ -604,12 +652,13 @@ class FnMaterial:
 
         return shader
 
-    def __get_shader(self):
+    def __get_shader(self) -> bpy.types.ShaderNodeTree:
         group_name = "MMDShaderDev"
         shader: bpy.types.ShaderNodeTree = bpy.data.node_groups.get(group_name, None) or bpy.data.node_groups.new(name=group_name, type="ShaderNodeTree")
         if len(shader.nodes):
             return shader
 
+        logger.debug(f"Creating MMD shader node group")
         ng = _NodeGroupUtils(shader)
 
         ############################################################################
@@ -699,15 +748,18 @@ class FnMaterial:
 
 class MigrationFnMaterial:
     @staticmethod
-    def update_mmd_shader():
+    def update_mmd_shader() -> None:
         mmd_shader_node_tree: Optional[bpy.types.NodeTree] = bpy.data.node_groups.get("MMDShaderDev")
         if mmd_shader_node_tree is None:
+            logger.debug("No MMD shader node tree found, skipping update")
             return
 
         ng = _NodeGroupUtils(mmd_shader_node_tree)
         if "Color" in ng.node_output.inputs:
+            logger.debug("MMD shader already has Color output, skipping update")
             return
 
+        logger.info("Updating MMD shader node tree")
         shader_diffuse: bpy.types.ShaderNodeBsdfDiffuse = [n for n in mmd_shader_node_tree.nodes if n.type == "BSDF_DIFFUSE"][0]
         node_sphere: bpy.types.ShaderNodeMixRGB = shader_diffuse.inputs["Color"].links[0].from_node
         node_output: bpy.types.NodeGroupOutput = ng.node_output
@@ -716,3 +768,11 @@ class MigrationFnMaterial:
 
         ng.new_output_socket("Color", node_sphere.outputs["Color"])
         ng.new_output_socket("Alpha", node_alpha.outputs["Value"])
+        logger.info("MMD shader node tree updated successfully")
+        
+        # Add Self Shadow input if it doesn't exist
+        if "Self Shadow" not in ng.node_input.outputs:
+            logger.info("Adding Self Shadow input to MMD shader")
+            # Find shader_base_mix node to connect Self Shadow
+            shader_base_mix = shader_alpha_mix.inputs[2].links[0].from_node
+            ng.new_input_socket("Self Shadow", shader_base_mix.inputs["Fac"], 0, min_max=(0, 1))

core/mmd/core/model.py

@@ -6,9 +6,8 @@
 # MMD Tools is licensed under the terms of the GNU General Public License version 3 (GPLv3) same as Avatar Toolkit.
 
 import itertools
-import logging
 import time
-from typing import TYPE_CHECKING, Any, Callable, Dict, Iterable, Iterator, Optional, Set, TypeGuard, Union, cast
+from typing import TYPE_CHECKING, Any, Callable, Dict, Iterable, Iterator, Optional, Set, TypeGuard, Union, cast, List, Tuple
 
 import bpy
 import idprop
@@ -20,15 +19,17 @@ from ..bpyutils import FnContext, Props
 from . import rigid_body
 from .morph import FnMorph
 from .rigid_body import MODE_DYNAMIC, MODE_DYNAMIC_BONE, MODE_STATIC
+from ....core.logging_setup import logger
 
 if TYPE_CHECKING:
     from ..properties.morph import MaterialMorphData
     from ..properties.rigid_body import MMDRigidBody
+    from bpy.types import Context, Object, PropertyGroup, Material, Mesh, Armature, EditBone, PoseBone, KinematicConstraint
 
 
 class FnModel:
     @staticmethod
-    def copy_mmd_root(destination_root_object: bpy.types.Object, source_root_object: bpy.types.Object, overwrite: bool = True, replace_name2values: Dict[str, Dict[Any, Any]] = None):
+    def copy_mmd_root(destination_root_object: bpy.types.Object, source_root_object: bpy.types.Object, overwrite: bool = True, replace_name2values: Optional[Dict[str, Dict[Any, Any]]] = None) -> None:
         FnModel.__copy_property(destination_root_object.mmd_root, source_root_object.mmd_root, overwrite=overwrite, replace_name2values=replace_name2values or {})
 
     @staticmethod
@@ -213,7 +214,8 @@ class FnModel:
         return obj is not None and obj.type == "MESH" and obj.mmd_type == "NONE"
 
     @staticmethod
-    def join_models(parent_root_object: bpy.types.Object, child_root_objects: Iterable[bpy.types.Object]):
+    def join_models(parent_root_object: bpy.types.Object, child_root_objects: Iterable[bpy.types.Object]) -> None:
+        logger.info(f"Joining models to parent root: {parent_root_object.name}")
         parent_armature_object = FnModel.find_armature_object(parent_root_object)
         with bpy.context.temp_override(
             active_object=parent_armature_object,
@@ -221,7 +223,7 @@ class FnModel:
         ):
             bpy.ops.object.transform_apply(location=True, rotation=True, scale=True)
 
-        def _change_bone_id(bone: bpy.types.PoseBone, new_bone_id: int, bone_morphs, pose_bones):
+        def _change_bone_id(bone: bpy.types.PoseBone, new_bone_id: int, bone_morphs: List[Any], pose_bones: List[bpy.types.PoseBone]) -> None:
             """This function will also update the references of bone morphs and rotate+/move+."""
             bone_id = bone.mmd_bone.bone_id
 
@@ -259,6 +261,7 @@ class FnModel:
 
         child_root_object: bpy.types.Object
         for child_root_object in child_root_objects:
+            logger.info(f"Processing child root: {child_root_object.name}")
             child_armature_object = FnModel.find_armature_object(child_root_object)
             child_pose_bones = child_armature_object.pose.bones
             child_bone_morphs = child_root_object.mmd_root.bone_morphs
@@ -279,7 +282,7 @@ class FnModel:
                 bpy.ops.object.transform_apply(location=True, rotation=True, scale=True)
 
             # Disconnect mesh dependencies because transform_apply fails when mesh data are multiple used.
-            related_meshes: Dict[MaterialMorphData, bpy.types.Mesh] = {}
+            related_meshes: Dict['MaterialMorphData', bpy.types.Mesh] = {}
             for material_morph in child_root_object.mmd_root.material_morphs:
                 for material_morph_data in material_morph.data:
                     if material_morph_data.related_mesh_data is not None:
@@ -353,6 +356,8 @@ class FnModel:
             if len(child_root_object.children) == 0:
                 bpy.data.objects.remove(child_root_object)
         
+        logger.info("Model joining completed successfully")
+
     @staticmethod
     def _add_armature_modifier(mesh_object: bpy.types.Object, armature_object: bpy.types.Object) -> bpy.types.ArmatureModifier:
         for m in mesh_object.modifiers:
@@ -369,10 +374,13 @@ class FnModel:
         return modifier
 
     @staticmethod
-    def attach_mesh_objects(parent_root_object: bpy.types.Object, mesh_objects: Iterable[bpy.types.Object], add_armature_modifier: bool):
+    def attach_mesh_objects(parent_root_object: bpy.types.Object, mesh_objects: Iterable[bpy.types.Object], add_armature_modifier: bool) -> None:
+        logger.info(f"Attaching mesh objects to {parent_root_object.name}")
         armature_object = FnModel.find_armature_object(parent_root_object)
         if armature_object is None:
-            raise ValueError(f"Armature object not found in {parent_root_object}")
+            error_msg = f"Armature object not found in {parent_root_object.name}"
+            logger.error(error_msg)
+            raise ValueError(error_msg)
 
         def __get_root_object(obj: bpy.types.Object) -> bpy.types.Object:
             if obj.parent is None:
@@ -381,9 +389,11 @@ class FnModel:
 
         for mesh_object in mesh_objects:
             if not FnModel.is_mesh_object(mesh_object):
+                logger.debug(f"Skipping non-mesh object: {mesh_object.name}")
                 continue
 
             if FnModel.find_root_object(mesh_object) is not None:
+                logger.debug(f"Skipping mesh with existing root: {mesh_object.name}")
                 continue
 
             mesh_root_object = __get_root_object(mesh_object)
@@ -391,15 +401,20 @@ class FnModel:
             mesh_root_object.parent_type = "OBJECT"
             mesh_root_object.parent = armature_object
             mesh_root_object.matrix_world = original_matrix_world
+            logger.debug(f"Attached mesh: {mesh_object.name}")
 
             if add_armature_modifier:
                 FnModel._add_armature_modifier(mesh_object, armature_object)
+                logger.debug(f"Added armature modifier to: {mesh_object.name}")
 
     @staticmethod
-    def add_missing_vertex_groups_from_bones(root_object: bpy.types.Object, mesh_object: bpy.types.Object, search_in_all_meshes: bool):
+    def add_missing_vertex_groups_from_bones(root_object: bpy.types.Object, mesh_object: bpy.types.Object, search_in_all_meshes: bool) -> None:
+        logger.info(f"Adding missing vertex groups from bones to {mesh_object.name}")
         armature_object = FnModel.find_armature_object(root_object)
         if armature_object is None:
-            raise ValueError(f"Armature object not found in {root_object}")
+            error_msg = f"Armature object not found in {root_object.name}"
+            logger.error(error_msg)
+            raise ValueError(error_msg)
 
         vertex_group_names: Set[str] = set()
 
@@ -408,6 +423,7 @@ class FnModel:
         for search_mesh in search_meshes:
             vertex_group_names.update(search_mesh.vertex_groups.keys())
 
+        added_count = 0
         pose_bone: bpy.types.PoseBone
         for pose_bone in armature_object.pose.bones:
             pose_bone_name = pose_bone.name
@@ -419,28 +435,34 @@ class FnModel:
                 continue
 
             mesh_object.vertex_groups.new(name=pose_bone_name)
+            added_count += 1
+        
+        logger.debug(f"Added {added_count} missing vertex groups to {mesh_object.name}")
 
     @staticmethod
-    def change_mmd_ik_loop_factor(root_object: bpy.types.Object, new_ik_loop_factor: int):
+    def change_mmd_ik_loop_factor(root_object: bpy.types.Object, new_ik_loop_factor: int) -> None:
+        logger.info(f"Changing IK loop factor to {new_ik_loop_factor}")
         mmd_root = root_object.mmd_root
         old_ik_loop_factor = mmd_root.ik_loop_factor
 
         if new_ik_loop_factor == old_ik_loop_factor:
+            logger.debug("IK loop factor already set to the requested value")
             return
 
         armature_object = FnModel.find_armature_object(root_object)
+        updated_count = 0
         for pose_bone in armature_object.pose.bones:
             for constraint in (cast(bpy.types.KinematicConstraint, c) for c in pose_bone.constraints if c.type == "IK"):
                 iterations = int(constraint.iterations * new_ik_loop_factor / old_ik_loop_factor)
-                logging.info("Update %s of %s: %d -> %d", constraint.name, pose_bone.name, constraint.iterations, iterations)
+                logger.debug(f"Update {constraint.name} of {pose_bone.name}: {constraint.iterations} -> {iterations}")
                 constraint.iterations = iterations
+                updated_count += 1
 
         mmd_root.ik_loop_factor = new_ik_loop_factor
-
+        logger.info(f"Updated {updated_count} IK constraints")
-        return
 
     @staticmethod
-    def __copy_property_group(destination: bpy.types.PropertyGroup, source: bpy.types.PropertyGroup, overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]):
+    def __copy_property_group(destination: bpy.types.PropertyGroup, source: bpy.types.PropertyGroup, overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]) -> None:
         destination_rna_properties = destination.bl_rna.properties
         for name in source.keys():
             is_attr = hasattr(source, name)
@@ -466,7 +488,7 @@ class FnModel:
                         destination[name] = value
 
     @staticmethod
-    def __copy_collection_property(destination: bpy.types.bpy_prop_collection, source: bpy.types.bpy_prop_collection, overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]):
+    def __copy_collection_property(destination: bpy.types.bpy_prop_collection, source: bpy.types.bpy_prop_collection, overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]) -> None:
         if overwrite:
             destination.clear()
 
@@ -499,16 +521,19 @@ class FnModel:
                 FnModel.__copy_property(destination[index], source[index], overwrite=True, replace_name2values=replace_name2values)
 
     @staticmethod
-    def __copy_property(destination: Union[bpy.types.PropertyGroup, bpy.types.bpy_prop_collection], source: Union[bpy.types.PropertyGroup, bpy.types.bpy_prop_collection], overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]):
+    def __copy_property(destination: Union[bpy.types.PropertyGroup, bpy.types.bpy_prop_collection], source: Union[bpy.types.PropertyGroup, bpy.types.bpy_prop_collection], overwrite: bool, replace_name2values: Dict[str, Dict[Any, Any]]) -> None:
         if isinstance(destination, bpy.types.PropertyGroup):
             FnModel.__copy_property_group(destination, source, overwrite=overwrite, replace_name2values=replace_name2values)
         elif isinstance(destination, bpy.types.bpy_prop_collection):
             FnModel.__copy_collection_property(destination, source, overwrite=overwrite, replace_name2values=replace_name2values)
         else:
-            raise ValueError(f"Unsupported destination: {destination}")
+            error_msg = f"Unsupported destination: {destination}"
+            logger.error(error_msg)
+            raise ValueError(error_msg)
 
     @staticmethod
-    def initalize_display_item_frames(root_object: bpy.types.Object, reset: bool = True):
+    def initalize_display_item_frames(root_object: bpy.types.Object, reset: bool = True) -> None:
+        logger.info(f"Initializing display item frames for {root_object.name}")
         frames = root_object.mmd_root.display_item_frames
         if reset and len(frames) > 0:
             root_object.mmd_root.active_display_item_frame = 0
@@ -532,6 +557,8 @@ class FnModel:
             frames.move(frames.find("Root"), 0)
             frames.move(frames.find("表情"), 1)
         
+        logger.debug(f"Display item frames initialized with {len(frames)} frames")
+
     @staticmethod
     def get_empty_display_size(root_object: bpy.types.Object) -> float:
         return getattr(root_object, Props.empty_display_size)
@@ -541,19 +568,28 @@ class MigrationFnModel:
     """Migration Functions for old MMD models broken by bugs or issues"""
 
     @classmethod
-    def update_mmd_ik_loop_factor(cls):
+    def update_mmd_ik_loop_factor(cls) -> None:
+        logger.info("Updating MMD IK loop factor for all armatures")
+        updated_count = 0
         for armature_object in bpy.data.objects:
             if armature_object.type != "ARMATURE":
                 continue
 
             if "mmd_ik_loop_factor" not in armature_object:
-                return
+                continue
 
-            FnModel.find_root_object(armature_object).mmd_root.ik_loop_factor = max(armature_object["mmd_ik_loop_factor"], 1)
+            root_object = FnModel.find_root_object(armature_object)
+            if root_object:
+                root_object.mmd_root.ik_loop_factor = max(armature_object["mmd_ik_loop_factor"], 1)
                 del armature_object["mmd_ik_loop_factor"]
+                updated_count += 1
+        
+        logger.info(f"Updated IK loop factor for {updated_count} armatures")
 
     @staticmethod
-    def update_avatar_toolkit_version():
+    def update_avatar_toolkit_version() -> None:
+        logger.info("Updating Avatar Toolkit version for all MMD root objects")
+        updated_count = 0
         for root_object in bpy.data.objects:
             if root_object.type != "EMPTY":
                 continue
@@ -565,10 +601,13 @@ class MigrationFnModel:
                 continue
 
             root_object["avatar_toolkit_version"] = "0.2.1"
+            updated_count += 1
+        
+        logger.info(f"Updated Avatar Toolkit version for {updated_count} root objects")
 
 
 class Model:
-    def __init__(self, root_obj):
+    def __init__(self, root_obj: bpy.types.Object) -> None:
         if root_obj is None:
             raise ValueError("must be MMD ROOT type object")
         if root_obj.mmd_type != "ROOT":
@@ -578,13 +617,15 @@ class Model:
         self.__rigid_grp: Optional[bpy.types.Object] = None
         self.__joint_grp: Optional[bpy.types.Object] = None
         self.__temporary_grp: Optional[bpy.types.Object] = None
+        logger.debug(f"Model initialized with root object: {self.__root.name}")
 
     @staticmethod
-    def create(name: str, name_e: str = "", scale: float = 1, obj_name: Optional[str] = None, armature_object: Optional[bpy.types.Object] = None, add_root_bone: bool = False):
+    def create(name: str, name_e: str = "", scale: float = 1, obj_name: Optional[str] = None, armature_object: Optional[bpy.types.Object] = None, add_root_bone: bool = False) -> 'Model':
         if obj_name is None:
             obj_name = name
 
         context = FnContext.ensure_context()
+        logger.info(f"Creating new MMD model: {name}")
 
         root: bpy.types.Object = bpy.data.objects.new(name=obj_name, object_data=None)
         root.mmd_type = "ROOT"
@@ -595,6 +636,7 @@ class Model:
         FnContext.link_object(context, root)
 
         if armature_object:
+            logger.debug(f"Using existing armature: {armature_object.name}")
             m = armature_object.matrix_world
             armature_object.parent_type = "OBJECT"
             armature_object.parent = root
@@ -602,6 +644,7 @@ class Model:
             root.matrix_world = m
             armature_object.matrix_local.identity()
         else:
+            logger.debug("Creating new armature")
             armature_object = bpy.data.objects.new(name=obj_name + "_arm", object_data=bpy.data.armatures.new(name=obj_name))
             armature_object.parent = root
             FnContext.link_object(context, armature_object)
@@ -614,6 +657,7 @@ class Model:
         FnBone.setup_special_bone_collections(armature_object)
 
         if add_root_bone:
+            logger.debug("Adding root bone")
             bone_name = "全ての親"
             bone_name_english = "Root"
 
@@ -637,34 +681,37 @@ class Model:
             bone_collection.assign(data_bone)
 
         FnContext.set_active_and_select_single_object(context, root)
+        logger.info(f"Model created successfully: {name}")
         return Model(root)
 
     @staticmethod
     def findRoot(obj: bpy.types.Object) -> Optional[bpy.types.Object]:
         return FnModel.find_root_object(obj)
 
-    def initialDisplayFrames(self, reset=True):
+    def initialDisplayFrames(self, reset: bool = True) -> None:
         FnModel.initalize_display_item_frames(self.__root, reset=reset)
 
     @property
-    def morph_slider(self):
+    def morph_slider(self) -> Any:
         return FnMorph.get_morph_slider(self)
 
-    def loadMorphs(self):
+    def loadMorphs(self) -> None:
+        logger.info(f"Loading morphs for model: {self.__root.name}")
         FnMorph.load_morphs(self)
 
-    def create_ik_constraint(self, bone, ik_target):
+    def create_ik_constraint(self, bone: bpy.types.PoseBone, ik_target: bpy.types.PoseBone) -> bpy.types.KinematicConstraint:
         """create IK constraint
 
         Args:
             bone: A pose bone to add a IK constraint
-            id_target: A pose bone for IK target
+            ik_target: A pose bone for IK target
 
         Returns:
             The bpy.types.KinematicConstraint object created. It is set target
             and subtarget options.
 
         """
+        logger.debug(f"Creating IK constraint on {bone.name} targeting {ik_target.name}")
         ik_target_name = ik_target.name
         ik_const = bone.constraints.new("IK")
         ik_const.target = self.__arm
@@ -693,6 +740,7 @@ class Model:
         if self.__rigid_grp is None:
             self.__rigid_grp = FnModel.find_rigid_group_object(self.__root)
             if self.__rigid_grp is None:
+                logger.debug(f"Creating rigid group object for {self.__root.name}")
                 rigids = bpy.data.objects.new(name="rigidbodies", object_data=None)
                 FnContext.link_object(FnContext.ensure_context(), rigids)
                 rigids.mmd_type = "RIGID_GRP_OBJ"
@@ -710,6 +758,7 @@ class Model:
         if self.__joint_grp is None:
             self.__joint_grp = FnModel.find_joint_group_object(self.__root)
             if self.__joint_grp is None:
+                logger.debug(f"Creating joint group object for {self.__root.name}")
                 joints = bpy.data.objects.new(name="joints", object_data=None)
                 FnContext.link_object(FnContext.ensure_context(), joints)
                 joints.mmd_type = "JOINT_GRP_OBJ"
@@ -727,6 +776,7 @@ class Model:
         if self.__temporary_grp is None:
             self.__temporary_grp = FnModel.find_temporary_group_object(self.__root)
             if self.__temporary_grp is None:
+                logger.debug(f"Creating temporary group object for {self.__root.name}")
                 temporarys = bpy.data.objects.new(name="temporary", object_data=None)
                 FnContext.link_object(FnContext.ensure_context(), temporarys)
                 temporarys.mmd_type = "TEMPORARY_GRP_OBJ"
@@ -740,7 +790,7 @@ class Model:
     def meshes(self) -> Iterator[bpy.types.Object]:
         return FnModel.iterate_mesh_objects(self.__root)
 
-    def attachMeshes(self, meshes: Iterator[bpy.types.Object], add_armature_modifier: bool = True):
+    def attachMeshes(self, meshes: Iterator[bpy.types.Object], add_armature_modifier: bool = True) -> None:
         FnModel.attach_mesh_objects(self.rootObject(), meshes, add_armature_modifier)
 
     def firstMesh(self) -> Optional[bpy.types.Object]:
@@ -748,7 +798,7 @@ class Model:
             return i
         return None
 
-    def findMesh(self, mesh_name) -> Optional[bpy.types.Object]:
+    def findMesh(self, mesh_name: str) -> Optional[bpy.types.Object]:
         """
         Helper method to find a mesh by name
         """
@@ -787,25 +837,26 @@ class Model:
     def joints(self) -> Iterator[bpy.types.Object]:
         return FnModel.iterate_joint_objects(self.__root)
 
-    def temporaryObjects(self, rigid_track_only=False) -> Iterator[bpy.types.Object]:
+    def temporaryObjects(self, rigid_track_only: bool = False) -> Iterator[bpy.types.Object]:
         return FnModel.iterate_temporary_objects(self.__root, rigid_track_only)
 
     def materials(self) -> Iterator[bpy.types.Material]:
         """
         Helper method to list all materials in all meshes
         """
-        materials = {}  # Use dict instead of set to guarantee preserve order
+        materials: Dict[bpy.types.Material, int] = {}  # Use dict instead of set to guarantee preserve order
         for mesh in self.meshes():
             materials.update((slot.material, 0) for slot in mesh.material_slots if slot.material is not None)
         return iter(materials.keys())
 
-    def renameBone(self, old_bone_name, new_bone_name):
+    def renameBone(self, old_bone_name: str, new_bone_name: str) -> None:
         if old_bone_name == new_bone_name:
             return
+        logger.info(f"Renaming bone: {old_bone_name} -> {new_bone_name}")
         armature = self.armature()
         bone = armature.pose.bones[old_bone_name]
         bone.name = new_bone_name
-        new_bone_name = bone.name
+        new_bone_name = bone.name  # Get the actual name (might be adjusted by Blender)
 
         mmd_root = self.rootObject().mmd_root
         for frame in mmd_root.display_item_frames:
@@ -816,28 +867,31 @@ class Model:
             if old_bone_name in mesh.vertex_groups:
                 mesh.vertex_groups[old_bone_name].name = new_bone_name
 
-    def build(self, non_collision_distance_scale=1.5, collision_margin=1e-06):
+    def build(self, non_collision_distance_scale: float = 1.5, collision_margin: float = 1e-06) -> None:
+        logger.info(f"Building physics rig for {self.__root.name}")
         rigidbody_world_enabled = rigid_body.setRigidBodyWorldEnabled(False)
         if self.__root.mmd_root.is_built:
+            logger.info("Model is already built, cleaning first")
             self.clean()
         self.__root.mmd_root.is_built = True
-        logging.info("****************************************")
+        logger.info("****************************************")
-        logging.info(" Build rig")
+        logger.info(" Build rig")
-        logging.info("****************************************")
+        logger.info("****************************************")
         start_time = time.time()
         self.__preBuild()
         self.disconnectPhysicsBones()
         self.buildRigids(non_collision_distance_scale, collision_margin)
         self.buildJoints()
         self.__postBuild()
-        logging.info(" Finished building in %f seconds.", time.time() - start_time)
+        logger.info(" Finished building in %f seconds.", time.time() - start_time)
         rigid_body.setRigidBodyWorldEnabled(rigidbody_world_enabled)
 
-    def clean(self):
+    def clean(self) -> None:
+        logger.info(f"Cleaning physics rig for {self.__root.name}")
         rigidbody_world_enabled = rigid_body.setRigidBodyWorldEnabled(False)
-        logging.info("****************************************")
+        logger.info("****************************************")
-        logging.info(" Clean rig")
+        logger.info(" Clean rig")
-        logging.info("****************************************")
+        logger.info("****************************************")
         start_time = time.time()
 
         pose_bones = []
@@ -848,13 +902,14 @@ class Model:
             if "mmd_tools_rigid_track" in i.constraints:
                 const = i.constraints["mmd_tools_rigid_track"]
                 i.constraints.remove(const)
+                logger.debug(f"Removed rigid track constraint from {i.name}")
 
         rigid_track_counts = 0
         for i in self.rigidBodies():
             rigid_type = int(i.mmd_rigid.type)
             if "mmd_tools_rigid_parent" not in i.constraints:
                 rigid_track_counts += 1
-                logging.info('%3d# Create a "CHILD_OF" constraint for %s', rigid_track_counts, i.name)
+                logger.info('%3d# Create a "CHILD_OF" constraint for %s', rigid_track_counts, i.name)
                 i.mmd_rigid.bone = i.mmd_rigid.bone
             relation = i.constraints["mmd_tools_rigid_parent"]
             relation.mute = True
@@ -884,35 +939,39 @@ class Model:
         mmd_root = self.rootObject().mmd_root
         if mmd_root.show_temporary_objects:
             mmd_root.show_temporary_objects = False
-        logging.info(" Finished cleaning in %f seconds.", time.time() - start_time)
+        logger.info(" Finished cleaning in %f seconds.", time.time() - start_time)
         mmd_root.is_built = False
         rigid_body.setRigidBodyWorldEnabled(rigidbody_world_enabled)
 
-    def __removeTemporaryObjects(self):
+    def __removeTemporaryObjects(self) -> None:
+        logger.debug("Removing temporary objects")
         with bpy.context.temp_override(selected_objects=tuple(self.temporaryObjects()), active_object=self.rootObject()):
             bpy.ops.object.delete()
 
-    def __restoreTransforms(self, obj):
+    def __restoreTransforms(self, obj: bpy.types.Object) -> None:
         for attr in ("location", "rotation_euler"):
             attr_name = "__backup_%s__" % attr
             val = obj.get(attr_name, None)
             if val is not None:
                 setattr(obj, attr, val)
                 del obj[attr_name]
+                logger.debug(f"Restored {attr} for {obj.name}")
 
-    def __backupTransforms(self, obj):
+    def __backupTransforms(self, obj: bpy.types.Object) -> None:
         for attr in ("location", "rotation_euler"):
             attr_name = "__backup_%s__" % attr
             if attr_name in obj:  # should not happen in normal build/clean cycle
                 continue
             obj[attr_name] = getattr(obj, attr, None)
+            logger.debug(f"Backed up {attr} for {obj.name}")
 
-    def __preBuild(self):
+    def __preBuild(self) -> None:
-        self.__fake_parent_map = {}
+        logger.debug("Pre-build preparation")
-        self.__rigid_body_matrix_map = {}
+        self.__fake_parent_map: Dict[bpy.types.Object, List[bpy.types.Object]] = {}
-        self.__empty_parent_map = {}
+        self.__rigid_body_matrix_map: Dict[bpy.types.Object, Any] = {}
+        self.__empty_parent_map: Dict[bpy.types.Object, bpy.types.Object] = {}
 
-        no_parents = []
+        no_parents: List[bpy.types.Object] = []
         for i in self.rigidBodies():
             self.__backupTransforms(i)
             # mute relation
@@ -932,7 +991,7 @@ class Model:
         # update changes of armature constraints
         bpy.context.scene.frame_set(bpy.context.scene.frame_current)
 
-        parented = []
+        parented: List[bpy.types.Object] = []
         for i in self.joints():
             self.__backupTransforms(i)
             rbc = i.rigid_body_constraint
@@ -950,7 +1009,8 @@ class Model:
 
         # assert(len(no_parents) == len(parented))
 
-    def __postBuild(self):
+    def __postBuild(self) -> None:
+        logger.debug("Post-build finalization")
         self.__fake_parent_map = None
         self.__rigid_body_matrix_map = None
 
@@ -962,6 +1022,7 @@ class Model:
             matrix_world = empty.matrix_world
             empty.parent = rigid_obj
             empty.matrix_world = matrix_world
+            logger.debug(f"Parented empty {empty.name} to rigid object {rigid_obj.name}")
         self.__empty_parent_map = None
 
         arm = self.armature()
@@ -970,11 +1031,13 @@ class Model:
                 c = p_bone.constraints.get("mmd_tools_rigid_track", None)
                 if c:
                     c.mute = False
+                    logger.debug(f"Enabled rigid track constraint for {p_bone.name}")
 
-    def updateRigid(self, rigid_obj: bpy.types.Object, collision_margin: float):
+    def updateRigid(self, rigid_obj: bpy.types.Object, collision_margin: float) -> None:
         assert rigid_obj.mmd_type == "RIGID_BODY"
         rb = rigid_obj.rigid_body
         if rb is None:
+            logger.warning(f"No rigid body for {rigid_obj.name}")
             return
 
         rigid = rigid_obj.mmd_rigid
@@ -1018,7 +1081,7 @@ class Model:
                 fake_children = self.__fake_parent_map.get(rigid_obj, None)
                 if fake_children:
                     for fake_child in fake_children:
-                        logging.debug("          - fake_child: %s", fake_child.name)
+                        logger.debug("          - fake_child: %s", fake_child.name)
                         t, r, s = (m @ fake_child.matrix_local).decompose()
                         fake_child.location = t
                         fake_child.rotation_euler = r.to_euler(fake_child.rotation_mode)
@@ -1032,7 +1095,7 @@ class Model:
                 fake_children = self.__fake_parent_map.get(rigid_obj, None)
                 if fake_children:
                     for fake_child in fake_children:
-                        logging.debug("          - fake_child: %s", fake_child.name)
+                        logger.debug("          - fake_child: %s", fake_child.name)
                         t, r, s = (m @ fake_child.matrix_local).decompose()
                         fake_child.location = t
                         fake_child.rotation_euler = r.to_euler(fake_child.rotation_mode)
@@ -1062,7 +1125,7 @@ class Model:
                     ori_rigid_obj = self.__empty_parent_map[empty]
                     ori_rb = ori_rigid_obj.rigid_body
                     if ori_rb and rb.mass > ori_rb.mass:
-                        logging.debug("        * Bone (%s): change target from [%s] to [%s]", target_bone.name, ori_rigid_obj.name, rigid_obj.name)
+                        logger.debug("        * Bone (%s): change target from [%s] to [%s]", target_bone.name, ori_rigid_obj.name, rigid_obj.name)
                         # re-parenting
                         rigid_obj.mmd_rigid.bone = bone_name
                         rigid_obj.constraints.remove(relation)
@@ -1070,21 +1133,22 @@ class Model:
                         # revert change
                         ori_rigid_obj.mmd_rigid.bone = bone_name
                     else:
-                        logging.debug("        * Bone (%s): track target [%s]", target_bone.name, ori_rigid_obj.name)
+                        logger.debug("        * Bone (%s): track target [%s]", target_bone.name, ori_rigid_obj.name)
 
         rb.collision_shape = rigid.shape
+        logger.debug(f"Updated rigid body {rigid_obj.name} with type {rigid_type}")
 
-    def __getRigidRange(self, obj):
+    def __getRigidRange(self, obj: bpy.types.Object) -> float:
         return (Vector(obj.bound_box[0]) - Vector(obj.bound_box[6])).length
 
-    def __createNonCollisionConstraint(self, nonCollisionJointTable):
+    def __createNonCollisionConstraint(self, nonCollisionJointTable: List[Tuple[bpy.types.Object, bpy.types.Object]]) -> None:
         total_len = len(nonCollisionJointTable)
         if total_len < 1:
             return
 
         start_time = time.time()
-        logging.debug("-" * 60)
+        logger.debug("-" * 60)
-        logging.debug(" creating ncc, counts: %d", total_len)
+        logger.debug(" creating ncc, counts: %d", total_len)
 
         ncc_obj = bpyutils.createObject(name="ncc", object_data=None)
         ncc_obj.location = [0, 0, 0]
@@ -1099,26 +1163,26 @@ class Model:
         rb.disable_collisions = True
 
         ncc_objs = bpyutils.duplicateObject(ncc_obj, total_len)
-        logging.debug(" created %d ncc.", len(ncc_objs))
+        logger.debug(" created %d ncc.", len(ncc_objs))
 
         for ncc_obj, pair in zip(ncc_objs, nonCollisionJointTable):
             rbc = ncc_obj.rigid_body_constraint
             rbc.object1, rbc.object2 = pair
             ncc_obj.hide_set(True)
             ncc_obj.hide_select = True
-        logging.debug(" finish in %f seconds.", time.time() - start_time)
+        logger.debug(" finish in %f seconds.", time.time() - start_time)
-        logging.debug("-" * 60)
+        logger.debug("-" * 60)
 
-    def buildRigids(self, non_collision_distance_scale, collision_margin):
+    def buildRigids(self, non_collision_distance_scale: float, collision_margin: float) -> List[bpy.types.Object]:
-        logging.debug("--------------------------------")
+        logger.debug("--------------------------------")
-        logging.debug(" Build riggings of rigid bodies")
+        logger.debug(" Build riggings of rigid bodies")
-        logging.debug("--------------------------------")
+        logger.debug("--------------------------------")
         rigid_objects = list(self.rigidBodies())
-        rigid_object_groups = [[] for i in range(16)]
+        rigid_object_groups: List[List[bpy.types.Object]] = [[] for i in range(16)]
         for i in rigid_objects:
             rigid_object_groups[i.mmd_rigid.collision_group_number].append(i)
 
-        jointMap = {}
+        jointMap: Dict[frozenset, bpy.types.Object] = {}
         for joint in self.joints():
             rbc = joint.rigid_body_constraint
             if rbc is None:
@@ -1126,10 +1190,10 @@ class Model:
             rbc.disable_collisions = False
             jointMap[frozenset((rbc.object1, rbc.object2))] = joint
 
-        logging.info("Creating non collision constraints")
+        logger.info("Creating non collision constraints")
         # create non collision constraints
-        nonCollisionJointTable = []
+        nonCollisionJointTable: List[Tuple[bpy.types.Object, bpy.types.Object]] = []
-        non_collision_pairs = set()
+        non_collision_pairs: Set[frozenset] = set()
         rigid_object_cnt = len(rigid_objects)
         for obj_a in rigid_objects:
             for n, ignore in enumerate(obj_a.mmd_rigid.collision_group_mask):
@@ -1150,12 +1214,13 @@ class Model:
                             nonCollisionJointTable.append((obj_a, obj_b))
                     non_collision_pairs.add(pair)
         for cnt, i in enumerate(rigid_objects):
-            logging.info("%3d/%3d: Updating rigid body %s", cnt + 1, rigid_object_cnt, i.name)
+            logger.info("%3d/%3d: Updating rigid body %s", cnt + 1, rigid_object_cnt, i.name)
             self.updateRigid(i, collision_margin)
         self.__createNonCollisionConstraint(nonCollisionJointTable)
         return rigid_objects
 
-    def buildJoints(self):
+    def buildJoints(self) -> None:
+        logger.info("Building joints")
         for i in self.joints():
             rbc = i.rigid_body_constraint
             if rbc is None:
@@ -1168,8 +1233,9 @@ class Model:
             t, r, s = (m @ i.matrix_local).decompose()
             i.location = t
             i.rotation_euler = r.to_euler(i.rotation_mode)
+            logger.debug(f"Built joint: {i.name}")
 
-    def __editPhysicsBones(self, editor: Callable[[bpy.types.EditBone], None], target_modes: Set[str]):
+    def __editPhysicsBones(self, editor: Callable[[bpy.types.EditBone], None], target_modes: Set[str]) -> None:
         armature_object = self.armature()
 
         armature: bpy.types.Armature
@@ -1177,7 +1243,7 @@ class Model:
             edit_bones = armature.edit_bones
             rigid_body_object: bpy.types.Object
             for rigid_body_object in self.rigidBodies():
-                mmd_rigid: MMDRigidBody = rigid_body_object.mmd_rigid
+                mmd_rigid: 'MMDRigidBody' = rigid_body_object.mmd_rigid
                 if mmd_rigid.type not in target_modes:
                     continue
 
@@ -1188,21 +1254,25 @@ class Model:
 
                 editor(edit_bone)
 
-    def disconnectPhysicsBones(self):
+    def disconnectPhysicsBones(self) -> None:
-        def editor(edit_bone: bpy.types.EditBone):
+        logger.info("Disconnecting physics bones")
+        def editor(edit_bone: bpy.types.EditBone) -> None:
             rna_prop_ui.rna_idprop_ui_create(edit_bone, "mmd_bone_use_connect", default=edit_bone.use_connect)
             edit_bone.use_connect = False
+            logger.debug(f"Disconnected bone: {edit_bone.name}")
 
         self.__editPhysicsBones(editor, {str(MODE_DYNAMIC)})
 
-    def connectPhysicsBones(self):
+    def connectPhysicsBones(self) -> None:
-        def editor(edit_bone: bpy.types.EditBone):
+        logger.info("Connecting physics bones")
+        def editor(edit_bone: bpy.types.EditBone) -> None:
             mmd_bone_use_connect_str: Optional[str] = edit_bone.get("mmd_bone_use_connect")
             if mmd_bone_use_connect_str is None:
                 return
 
             if not edit_bone.use_connect:  # wasn't it overwritten?
                 edit_bone.use_connect = bool(mmd_bone_use_connect_str)
+                logger.debug(f"Connected bone: {edit_bone.name}")
             del edit_bone["mmd_bone_use_connect"]
 
         self.__editPhysicsBones(editor, {str(MODE_STATIC), str(MODE_DYNAMIC), str(MODE_DYNAMIC_BONE)})

core/mmd/core/morph.py

@@ -5,33 +5,35 @@
 # Neoneko has modified this file to work with Avatar Toolkit and may of made changes or improvements.
 # MMD Tools is licensed under the terms of the GNU General Public License version 3 (GPLv3) same as Avatar Toolkit.
 
-import logging
 import re
-from typing import TYPE_CHECKING, Tuple, cast
+from typing import TYPE_CHECKING, Tuple, cast, List, Dict, Optional, Set, Any, Union, Iterator
 
 import bpy
+import numpy as np
+from bpy.types import Object, ShapeKey, Material, Mesh, Armature, PoseBone, Constraint
 
 from .. import bpyutils, utils
 from ..bpyutils import FnContext, FnObject, TransformConstraintOp
+from ....core.logging_setup import logger
 
 if TYPE_CHECKING:
     from .model import Model
 
 
 class FnMorph:
-    def __init__(self, morph, model: "Model"):
+    def __init__(self, morph: Any, model: "Model"):
         self.__morph = morph
         self.__rig = model
 
     @classmethod
-    def storeShapeKeyOrder(cls, obj, shape_key_names):
+    def storeShapeKeyOrder(cls, obj: Object, shape_key_names: List[str]) -> None:
         if len(shape_key_names) < 1:
             return
         assert FnContext.get_active_object(FnContext.ensure_context()) == obj
         if obj.data.shape_keys is None:
             bpy.ops.object.shape_key_add()
 
-        def __move_to_bottom(key_blocks, name):
+        def __move_to_bottom(key_blocks: bpy.types.bpy_prop_collection, name: str) -> None:
             obj.active_shape_key_index = key_blocks.find(name)
             bpy.ops.object.shape_key_move(type="BOTTOM")
 
@@ -43,7 +45,7 @@ class FnMorph:
                 __move_to_bottom(key_blocks, name)
 
     @classmethod
-    def fixShapeKeyOrder(cls, obj, shape_key_names):
+    def fixShapeKeyOrder(cls, obj: Object, shape_key_names: List[str]) -> None:
         if len(shape_key_names) < 1:
             return
         assert FnContext.get_active_object(FnContext.ensure_context()) == obj
@@ -58,11 +60,11 @@ class FnMorph:
             bpy.ops.object.shape_key_move(type="BOTTOM")
 
     @staticmethod
-    def get_morph_slider(rig):
+    def get_morph_slider(rig: "Model") -> "_MorphSlider":
         return _MorphSlider(rig)
 
     @staticmethod
-    def category_guess(morph):
+    def category_guess(morph: Any) -> None:
         name_lower = morph.name.lower()
         if "mouth" in name_lower:
             morph.category = "MOUTH"
@@ -73,7 +75,7 @@ class FnMorph:
                 morph.category = "EYE"
 
     @classmethod
-    def load_morphs(cls, rig):
+    def load_morphs(cls, rig: "Model") -> None:
         mmd_root = rig.rootObject().mmd_root
         vertex_morphs = mmd_root.vertex_morphs
         uv_morphs = mmd_root.uv_morphs
@@ -92,7 +94,7 @@ class FnMorph:
                     cls.category_guess(item)
 
     @staticmethod
-    def remove_shape_key(mesh_object: bpy.types.Object, shape_key_name: str):
+    def remove_shape_key(mesh_object: Object, shape_key_name: str) -> None:
         assert isinstance(mesh_object.data, bpy.types.Mesh)
 
         shape_keys = mesh_object.data.shape_keys
@@ -104,7 +106,7 @@ class FnMorph:
             FnObject.mesh_remove_shape_key(mesh_object, key_blocks[shape_key_name])
 
     @staticmethod
-    def copy_shape_key(mesh_object: bpy.types.Object, src_name: str, dest_name: str):
+    def copy_shape_key(mesh_object: Object, src_name: str, dest_name: str) -> None:
         assert isinstance(mesh_object.data, bpy.types.Mesh)
 
         shape_keys = mesh_object.data.shape_keys
@@ -126,13 +128,13 @@ class FnMorph:
         mesh_object.active_shape_key_index = key_blocks.find(dest_name)
 
     @staticmethod
-    def get_uv_morph_vertex_groups(obj, morph_name=None, offset_axes="XYZW"):
+    def get_uv_morph_vertex_groups(obj: Object, morph_name: Optional[str] = None, offset_axes: str = "XYZW") -> Iterator[Tuple[bpy.types.VertexGroup, str, str]]:
         pattern = "UV_%s[+-][%s]$" % (morph_name or ".{1,}", offset_axes or "XYZW")
         # yield (vertex_group, morph_name, axis),...
         return ((g, g.name[3:-2], g.name[-2:]) for g in obj.vertex_groups if re.match(pattern, g.name))
 
     @staticmethod
-    def copy_uv_morph_vertex_groups(obj, src_name, dest_name):
+    def copy_uv_morph_vertex_groups(obj: Object, src_name: str, dest_name: str) -> None:
         for vg, n, x in FnMorph.get_uv_morph_vertex_groups(obj, dest_name):
             obj.vertex_groups.remove(vg)
 
@@ -143,12 +145,12 @@ class FnMorph:
             obj.vertex_groups.active.name = vg_name.replace(src_name, dest_name)
 
     @staticmethod
-    def overwrite_bone_morphs_from_action_pose(armature_object):
+    def overwrite_bone_morphs_from_action_pose(armature_object: Object) -> None:
         armature = armature_object.id_data
         
         # Use animation_data and action instead of action_pose
         if armature.animation_data is None or armature.animation_data.action is None:
-            logging.warning('[WARNING] armature "%s" has no animation data or action', armature_object.name)
+            logger.warning('Armature "%s" has no animation data or action', armature_object.name)
             return
 
         action = armature.animation_data.action
@@ -187,9 +189,9 @@ class FnMorph:
         utils.selectAObject(root)
 
     @staticmethod
-    def clean_uv_morph_vertex_groups(obj):
+    def clean_uv_morph_vertex_groups(obj: Object) -> None:
         # remove empty vertex groups of uv morphs
-        vg_indices = {g.index for g, n, x in FnMorph.get_uv_morph_vertex_groups(obj)}
+        vg_indices: Set[int] = {g.index for g, n, x in FnMorph.get_uv_morph_vertex_groups(obj)}
         vertex_groups = obj.vertex_groups
         for v in obj.data.vertices:
             for x in v.groups:
@@ -203,8 +205,8 @@ class FnMorph:
             vertex_groups.remove(vg)
 
     @staticmethod
-    def get_uv_morph_offset_map(obj, morph):
+    def get_uv_morph_offset_map(obj: Object, morph: Any) -> Dict[int, List[float]]:
-        offset_map = {}  # offset_map[vertex_index] = offset_xyzw
+        offset_map: Dict[int, List[float]] = {}  # offset_map[vertex_index] = offset_xyzw
         if morph.data_type == "VERTEX_GROUP":
             scale = morph.vertex_group_scale
             axis_map = {g.index: x for g, n, x in FnMorph.get_uv_morph_vertex_groups(obj, morph.name)}
@@ -225,7 +227,7 @@ class FnMorph:
         return offset_map
 
     @staticmethod
-    def store_uv_morph_data(obj, morph, offsets=None, offset_axes="XYZW"):
+    def store_uv_morph_data(obj: Object, morph: Any, offsets: Optional[List[Any]] = None, offset_axes: str = "XYZW") -> None:
         vertex_groups = obj.vertex_groups
         morph_name = getattr(morph, "name", None)
         if offset_axes:
@@ -250,7 +252,7 @@ class FnMorph:
                     vg = vertex_groups.get(vg_name, None) or vertex_groups.new(name=vg_name)
                     vg.add(index=[idx], weight=abs(val) / scale, type="REPLACE")
 
-    def update_mat_related_mesh(self, new_mesh=None):
+    def update_mat_related_mesh(self, new_mesh: Optional[Object] = None) -> None:
         for offset in self.__morph.data:
             # Use the new_mesh if provided
             meshObj = new_mesh
@@ -270,11 +272,11 @@ class FnMorph:
                 offset.related_mesh = meshObj.data.name
 
     @staticmethod
-    def clean_duplicated_material_morphs(mmd_root_object: bpy.types.Object):
+    def clean_duplicated_material_morphs(mmd_root_object: Object) -> None:
         """Clean duplicated material_morphs and data from mmd_root_object.mmd_root.material_morphs[].data[]"""
         mmd_root = mmd_root_object.mmd_root
 
-        def morph_data_equals(l, r) -> bool:
+        def morph_data_equals(l: Any, r: Any) -> bool:
             return (
                 l.related_mesh_data == r.related_mesh_data
                 and l.offset_type == r.offset_type
@@ -290,7 +292,7 @@ class FnMorph:
                 and all(a == b for a, b in zip(l.toon_texture_factor, r.toon_texture_factor))
             )
 
-        def morph_equals(l, r) -> bool:
+        def morph_equals(l: Any, r: Any) -> bool:
             return len(l.data) == len(r.data) and all(morph_data_equals(a, b) for a, b in zip(l.data, r.data))
 
         # Remove duplicated mmd_root.material_morphs.data[]
@@ -325,7 +327,7 @@ class _MorphSlider:
     def __init__(self, model: "Model"):
         self.__rig = model
 
-    def placeholder(self, create=False, binded=False):
+    def placeholder(self, create: bool = False, binded: bool = False) -> Optional[Object]:
         rig = self.__rig
         root = rig.rootObject()
         obj = next((x for x in root.children if x.mmd_type == "PLACEHOLDER" and x.type == "MESH"), None)
@@ -343,11 +345,11 @@ class _MorphSlider:
         return obj
 
     @property
-    def dummy_armature(self):
+    def dummy_armature(self) -> Optional[Object]:
         obj = self.placeholder()
         return self.__dummy_armature(obj) if obj else None
 
-    def __dummy_armature(self, obj, create=False):
+    def __dummy_armature(self, obj: Object, create: bool = False) -> Optional[Object]:
         arm = next((x for x in obj.children if x.mmd_type == "PLACEHOLDER" and x.type == "ARMATURE"), None)
         if create and arm is None:
             arm = bpy.data.objects.new(name=".dummy_armature", object_data=bpy.data.armatures.new(name=".dummy_armature"))
@@ -360,7 +362,7 @@ class _MorphSlider:
             FnBone.setup_special_bone_collections(arm)
         return arm
 
-    def get(self, morph_name):
+    def get(self, morph_name: str) -> Optional[ShapeKey]:
         obj = self.placeholder()
         if obj is None:
             return None
@@ -369,13 +371,13 @@ class _MorphSlider:
             return None
         return key_blocks.get(morph_name, None)
 
-    def create(self):
+    def create(self) -> Object:
         self.__rig.loadMorphs()
         obj = self.placeholder(create=True)
         self.__load(obj, self.__rig.rootObject().mmd_root)
         return obj
 
-    def __load(self, obj, mmd_root):
+    def __load(self, obj: Object, mmd_root: Any) -> None:
         attr_list = ("group", "vertex", "bone", "uv", "material")
         morph_sliders = obj.data.shape_keys.key_blocks
         for m in (x for attr in attr_list for x in getattr(mmd_root, attr + "_morphs", ())):
@@ -386,7 +388,7 @@ class _MorphSlider:
                 obj.shape_key_add(name=name, from_mix=False)
 
     @staticmethod
-    def __driver_variables(id_data, path, index=-1):
+    def __driver_variables(id_data: Any, path: str, index: int = -1) -> Tuple[Any, Any]:
         d = id_data.driver_add(path, index)
         variables = d.driver.variables
         for x in variables:
@@ -394,7 +396,7 @@ class _MorphSlider:
         return d.driver, variables
 
     @staticmethod
-    def __add_single_prop(variables, id_obj, data_path, prefix):
+    def __add_single_prop(variables: Any, id_obj: Object, data_path: str, prefix: str) -> Any:
         var = variables.new()
         var.name = f"{prefix}{len(variables)}"
         var.type = "SINGLE_PROP"
@@ -405,7 +407,7 @@ class _MorphSlider:
         return var
 
     @staticmethod
-    def __shape_key_driver_check(key_block, resolve_path=False):
+    def __shape_key_driver_check(key_block: ShapeKey, resolve_path: bool = False) -> bool:
         if resolve_path:
             try:
                 key_block.id_data.path_resolve(key_block.path_from_id())
@@ -419,7 +421,7 @@ class _MorphSlider:
             d = next((i for i in key_block.id_data.animation_data.drivers if i.data_path == data_path), None)
         return not d or d.driver.expression == "".join(("*w", "+g", "v")[-1 if i < 1 else i % 2] + str(i + 1) for i in range(len(d.driver.variables)))
 
-    def __cleanup(self, names_in_use=None):
+    def __cleanup(self, names_in_use: Optional[Dict[str, Any]] = None) -> None:
         from math import ceil, floor
 
         names_in_use = names_in_use or {}
@@ -427,7 +429,7 @@ class _MorphSlider:
         morph_sliders = self.placeholder()
         morph_sliders = morph_sliders.data.shape_keys.key_blocks if morph_sliders else {}
         for mesh_object in rig.meshes():
-            for kb in getattr(mesh_object.data.shape_keys, "key_blocks", cast(Tuple[bpy.types.ShapeKey], ())):
+            for kb in getattr(mesh_object.data.shape_keys, "key_blocks", cast(Tuple[ShapeKey], ())):
                 if kb.name in names_in_use:
                     continue
 
@@ -465,7 +467,7 @@ class _MorphSlider:
                         c.driver_remove(attr)
                     b.constraints.remove(c)
 
-    def unbind(self):
+    def unbind(self) -> None:
         mmd_root = self.__rig.rootObject().mmd_root
 
         # after unbind, the weird lag problem will disappear.
@@ -488,7 +490,7 @@ class _MorphSlider:
                         b.driver_remove("rotation_quaternion")
         self.__cleanup()
 
-    def bind(self):
+    def bind(self) -> None:
         rig = self.__rig
         root = rig.rootObject()
         armObj = rig.armature()
@@ -502,10 +504,10 @@ class _MorphSlider:
         morph_sliders = obj.data.shape_keys.key_blocks
 
         # data gathering
-        group_map = {}
+        group_map: Dict[Tuple[str, str], List[List[Any]]] = {}
 
-        shape_key_map = {}
+        shape_key_map: Dict[str, List[Tuple[ShapeKey, str, List[Any]]]] = {}
-        uv_morph_map = {}
+        uv_morph_map: Dict[str, List[Tuple[str, str, str, List[Any]]]] = {}
         for mesh_object in rig.meshes():
             mesh_object.show_only_shape_key = False
             key_blocks = getattr(mesh_object.data.shape_keys, "key_blocks", ())
@@ -526,7 +528,7 @@ class _MorphSlider:
                 kb_bind.slider_max = 10
 
                 data_path = 'data.shape_keys.key_blocks["%s"].value' % kb_name.replace('"', '\\"')
-                groups = []
+                groups: List[Any] = []
                 shape_key_map.setdefault(name_bind, []).append((kb_bind, data_path, groups))
                 group_map.setdefault(("vertex_morphs", kb_name), []).append(groups)
 
@@ -542,7 +544,7 @@ class _MorphSlider:
                     continue
 
                 name_bind = "mmd_bind%s" % hash(vg.name)
-                uv_morph_map.setdefault(name_bind, ())
+                uv_morph_map.setdefault(name_bind, [])
                 mod = mesh_object.modifiers.get(name_bind, None) or mesh_object.modifiers.new(name=name_bind, type="UV_WARP")
                 mod.show_expanded = False
                 mod.vertex_group = vg.name
@@ -555,13 +557,13 @@ class _MorphSlider:
                 else:
                     mod.bone_from, mod.bone_to = name_bind, "mmd_bind_ctrl_base"
 
-        bone_offset_map = {}
+        bone_offset_map: Dict[str, Tuple[str, Any, str, str, List[Any]]] = {}
         with bpyutils.edit_object(arm) as data:
             from .bone import FnBone
 
             edit_bones = data.edit_bones
 
-            def __get_bone(name, parent):
+            def __get_bone(name: str, parent: Optional[bpy.types.EditBone]) -> bpy.types.EditBone:
                 b = edit_bones.get(name, None) or edit_bones.new(name=name)
                 b.head = (0, 0, 0)
                 b.tail = (0, 0, 1)
@@ -578,7 +580,7 @@ class _MorphSlider:
                         continue
                     d.name = name_bind = f"mmd_bind{hash(d)}"
                     b = FnBone.set_edit_bone_to_shadow(__get_bone(name_bind, None))
-                    groups = []
+                    groups: List[Any] = []
                     bone_offset_map[name_bind] = (m.name, d, b.name, data_path, groups)
                     group_map.setdefault(("bone_morphs", m.name), []).append(groups)
 
@@ -589,21 +591,21 @@ class _MorphSlider:
                 scale_path = f'mmd_root.uv_morphs["{morph_name}"].vertex_group_scale'
                 name_bind = f"mmd_bind{hash(m.name)}"
                 b = FnBone.set_edit_bone_to_dummy(__get_bone(name_bind, ctrl_base))
-                groups = []
+                groups: List[Any] = []
                 uv_morph_map.setdefault(name_bind, []).append((b.name, data_path, scale_path, groups))
                 group_map.setdefault(("uv_morphs", m.name), []).append(groups)
 
-            used_bone_names = bone_offset_map.keys() | uv_morph_map.keys()
+            used_bone_names: Set[str] = set(bone_offset_map.keys()) | set(uv_morph_map.keys())
             used_bone_names.add(ctrl_base.name)
             for b in edit_bones:  # cleanup
                 if b.name.startswith("mmd_bind") and b.name not in used_bone_names:
                     edit_bones.remove(b)
 
-        material_offset_map = {}
+        material_offset_map: Dict[str, Any] = {}
         for m in mmd_root.material_morphs:
             morph_name = m.name.replace('"', '\\"')
             data_path = f'data.shape_keys.key_blocks["{morph_name}"].value'
-            groups = []
+            groups: List[Any] = []
             group_map.setdefault(("material_morphs", m.name), []).append(groups)
             material_offset_map.setdefault("group_dict", {})[m.name] = (data_path, groups)
             for d in m.data:
@@ -614,7 +616,7 @@ class _MorphSlider:
 
         for m in mmd_root.group_morphs:
             if len(m.data) != len(set(m.data.keys())):
-                logging.warning(' * Found duplicated morph data in Group Morph "%s"', m.name)
+                logger.warning('Found duplicated morph data in Group Morph "%s"', m.name)
             morph_name = m.name.replace('"', '\\"')
             morph_path = f'data.shape_keys.key_blocks["{morph_name}"].value'
             for d in m.data:
@@ -625,7 +627,7 @@ class _MorphSlider:
 
         self.__cleanup(shape_key_map.keys() | bone_offset_map.keys() | uv_morph_map.keys())
 
-        def __config_groups(variables, expression, groups):
+        def __config_groups(variables: Any, expression: str, groups: List[Any]) -> str:
             for g_name, morph_path, factor_path in groups:
                 var = self.__add_single_prop(variables, obj, morph_path, "g")
                 fvar = self.__add_single_prop(variables, root, factor_path, "w")
@@ -644,7 +646,7 @@ class _MorphSlider:
             kb_bind.mute = False
 
         # bone morphs
-        def __config_bone_morph(constraints, map_type, attributes, val, val_str):
+        def __config_bone_morph(constraints: bpy.types.ArmatureConstraints, map_type: str, attributes: Set[str], val: float, val_str: str) -> None:
             c_name = f"mmd_bind{hash(data)}.{map_type[:3]}"
             c = TransformConstraintOp.create(constraints, c_name, map_type)
             TransformConstraintOp.update_min_max(c, val, None)
@@ -692,7 +694,7 @@ class _MorphSlider:
 
         group_dict = material_offset_map.get("group_dict", {})
 
-        def __config_material_morph(mat, morph_list):
+        def __config_material_morph(mat: Material, morph_list: List[Tuple[str, Any, str]]) -> None:
             nodes = _MaterialMorph.setup_morph_nodes(mat, tuple(x[1] for x in morph_list))
             for (morph_name, data, name_bind), node in zip(morph_list, nodes):
                 node.label, node.name = morph_name, name_bind
@@ -704,7 +706,7 @@ class _MorphSlider:
         for mat in (m for m in rig.materials() if m and m.use_nodes and not m.name.startswith("mmd_")):
             mul_all, add_all = material_offset_map.get("#", ([], []))
             if mat.name == "":
-                logging.warning("Oh no. The material name should never empty.")
+                logger.warning("Oh no. The material name should never be empty.")
                 mul_list, add_list = [], []
             else:
                 mat_name = "#" + mat.name
@@ -720,7 +722,7 @@ class _MorphSlider:
 
 class MigrationFnMorph:
     @staticmethod
-    def update_mmd_morph():
+    def update_mmd_morph() -> None:
         from .material import FnMaterial
 
         for root in bpy.data.objects:
@@ -762,11 +764,11 @@ class MigrationFnMorph:
                             morph_data.related_mesh_data = bpy.data.meshes[related_mesh]
 
     @staticmethod
-    def ensure_material_id_not_conflict():
+    def ensure_material_id_not_conflict() -> None:
-        mat_ids_set = set()
+        mat_ids_set: Set[int] = set()
 
         # The reference library properties cannot be modified and bypassed in advance.
-        need_update_mat = []
+        need_update_mat: List[Material] = []
         for mat in bpy.data.materials:
             if mat.mmd_material.material_id < 0:
                 continue
@@ -781,7 +783,7 @@ class MigrationFnMorph:
             mat_ids_set.add(mat.mmd_material.material_id)
 
     @staticmethod
-    def compatible_with_old_version_mmd_tools():
+    def compatible_with_old_version_mmd_tools() -> None:
         MigrationFnMorph.ensure_material_id_not_conflict()
 
         for root in bpy.data.objects:

core/mmd/core/rigid_body.py

@@ -5,12 +5,13 @@
 # Neoneko has modified this file to work with Avatar Toolkit and may of made changes or improvements.
 # MMD Tools is licensed under the terms of the GNU General Public License version 3 (GPLv3) same as Avatar Toolkit.
 
-from typing import List, Optional
+from typing import List, Optional, Tuple, Union, Dict, Any, Set, cast
 
 import bpy
-from mathutils import Euler, Vector
+from mathutils import Euler, Vector, Matrix
 
 from ..bpyutils import FnContext, Props
+from ....core.logging_setup import logger
 
 SHAPE_SPHERE = 0
 SHAPE_BOX = 1
@@ -21,25 +22,30 @@ MODE_DYNAMIC = 1
 MODE_DYNAMIC_BONE = 2
 
 
-def shapeType(collision_shape):
+def shapeType(collision_shape: str) -> int:
+    """Convert collision shape name to type index"""
     return ("SPHERE", "BOX", "CAPSULE").index(collision_shape)
 
 
-def collisionShape(shape_type):
+def collisionShape(shape_type: int) -> str:
+    """Convert shape type index to collision shape name"""
     return ("SPHERE", "BOX", "CAPSULE")[shape_type]
 
 
-def setRigidBodyWorldEnabled(enable):
+def setRigidBodyWorldEnabled(enable: bool) -> bool:
+    """Enable or disable the rigid body world and return previous state"""
     if bpy.ops.rigidbody.world_add.poll():
+        logger.debug("Creating rigid body world")
         bpy.ops.rigidbody.world_add()
     rigidbody_world = bpy.context.scene.rigidbody_world
     enabled = rigidbody_world.enabled
     rigidbody_world.enabled = enable
+    logger.debug(f"Rigid body world enabled: {enable} (was: {enabled})")
     return enabled
 
 
 class RigidBodyMaterial:
-    COLORS = [
+    COLORS: List[int] = [
         0x7FDDD4,
         0xF0E68C,
         0xEE82EE,
@@ -59,10 +65,12 @@ class RigidBodyMaterial:
     ]
 
     @classmethod
-    def getMaterial(cls, number):
+    def getMaterial(cls, number: int) -> bpy.types.Material:
+        """Get or create a material for rigid bodies with the specified number"""
         number = int(number)
-        material_name = "mmd_tools_rigid_%d" % (number)
+        material_name = f"mmd_tools_rigid_{number}"
         if material_name not in bpy.data.materials:
+            logger.debug(f"Creating rigid body material: {material_name}")
             mat = bpy.data.materials.new(material_name)
             color = cls.COLORS[number]
             mat.diffuse_color[:3] = [((0xFF0000 & color) >> 16) / float(255), ((0x00FF00 & color) >> 8) / float(255), (0x0000FF & color) / float(255)]
@@ -89,9 +97,11 @@ class RigidBodyMaterial:
 class FnRigidBody:
     @staticmethod
     def new_rigid_body_objects(context: bpy.types.Context, parent_object: bpy.types.Object, count: int) -> List[bpy.types.Object]:
+        """Create multiple rigid body objects parented to the specified object"""
         if count < 1:
             return []
 
+        logger.debug(f"Creating {count} rigid body objects parented to {parent_object.name}")
         obj = FnRigidBody.new_rigid_body_object(context, parent_object)
 
         if count == 1:
@@ -101,6 +111,8 @@ class FnRigidBody:
 
     @staticmethod
     def new_rigid_body_object(context: bpy.types.Context, parent_object: bpy.types.Object) -> bpy.types.Object:
+        """Create a new rigid body object parented to the specified object"""
+        logger.debug(f"Creating new rigid body object parented to {parent_object.name}")
         obj = FnContext.new_and_link_object(context, name="Rigidbody", object_data=bpy.data.meshes.new(name="Rigidbody"))
         obj.parent = parent_object
         obj.mmd_type = "RIGID_BODY"
@@ -118,11 +130,11 @@ class FnRigidBody:
     @staticmethod
     def setup_rigid_body_object(
         obj: bpy.types.Object,
-        shape_type: str,
+        shape_type: int,
         location: Vector,
         rotation: Euler,
         size: Vector,
-        dynamics_type: str,
+        dynamics_type: int,
         collision_group_number: Optional[int] = None,
         collision_group_mask: Optional[List[bool]] = None,
         name: Optional[str] = None,
@@ -134,6 +146,8 @@ class FnRigidBody:
         linear_damping: Optional[float] = None,
         bounce: Optional[float] = None,
     ) -> bpy.types.Object:
+        """Set up a rigid body object with the specified parameters"""
+        logger.debug(f"Setting up rigid body object: {obj.name}")
         obj.location = location
         obj.rotation_euler = rotation
 
@@ -175,7 +189,8 @@ class FnRigidBody:
         return obj
 
     @staticmethod
-    def get_rigid_body_size(obj: bpy.types.Object):
+    def get_rigid_body_size(obj: bpy.types.Object) -> Tuple[float, float, float]:
+        """Get the size of a rigid body object based on its shape type"""
         assert obj.mmd_type == "RIGID_BODY"
 
         x0, y0, z0 = obj.bound_box[0]
@@ -195,10 +210,14 @@ class FnRigidBody:
             height = abs((z1 - z0) - diameter)
             return (radius, height, 0.0)
         else:
-            raise ValueError(f"Invalid shape type: {shape}")
+            error_msg = f"Invalid shape type: {shape}"
+            logger.error(error_msg)
+            raise ValueError(error_msg)
 
     @staticmethod
     def new_joint_object(context: bpy.types.Context, parent_object: bpy.types.Object, empty_display_size: float) -> bpy.types.Object:
+        """Create a new joint object parented to the specified object"""
+        logger.debug(f"Creating new joint object parented to {parent_object.name}")
         obj = FnContext.new_and_link_object(context, name="Joint", object_data=None)
         obj.parent = parent_object
         obj.mmd_type = "JOINT"
@@ -230,9 +249,11 @@ class FnRigidBody:
 
     @staticmethod
     def new_joint_objects(context: bpy.types.Context, parent_object: bpy.types.Object, count: int, empty_display_size: float) -> List[bpy.types.Object]:
+        """Create multiple joint objects parented to the specified object"""
         if count < 1:
             return []
 
+        logger.debug(f"Creating {count} joint objects parented to {parent_object.name}")
         obj = FnRigidBody.new_joint_object(context, parent_object, empty_display_size)
 
         if count == 1:
@@ -256,6 +277,8 @@ class FnRigidBody:
         name: str,
         name_e: Optional[str] = None,
     ) -> bpy.types.Object:
+        """Set up a joint object with the specified parameters"""
+        logger.debug(f"Setting up joint object: {obj.name} with name {name}")
         obj.name = f"J.{name}"
 
         obj.location = location

core/mmd/core/sdef.py

@@ -7,14 +7,19 @@
 
 import logging
 import time
+from typing import Dict, List, Tuple, Set, Optional, Any, Union, cast, TypeVar, Callable
 
 import bpy
-from mathutils import Matrix, Vector
+import numpy as np
+from mathutils import Matrix, Vector, Quaternion, Euler
+from bpy.types import Object, PoseBone, Pose, ShapeKey, Modifier, VertexGroup
 
 from ..bpyutils import FnObject
+from ....core.logging_setup import logger
 
+T = TypeVar('T')
 
-def _hash(v):
+def _hash(v: Union[Object, PoseBone, Pose]) -> int:
     if isinstance(v, (bpy.types.Object, bpy.types.PoseBone)):
         return hash(type(v).__name__ + v.name)
     elif isinstance(v, bpy.types.Pose):
@@ -24,23 +29,24 @@ def _hash(v):
 
 
 class FnSDEF:
-    g_verts = {}  # global cache
+    g_verts: Dict[int, Dict[Tuple[int, int], Tuple[PoseBone, PoseBone, List[Tuple[int, float, float, Vector, Vector, Vector]], List[int]]]] = {}  # global cache
-    g_shapekey_data = {}
+    g_shapekey_data: Dict[int, Optional[np.ndarray]] = {}
-    g_bone_check = {}
+    g_bone_check: Dict[int, Dict[Union[Tuple[int, int], str], Union[Tuple[Matrix, Matrix], bool]]] = {}
-    __g_armature_check = {}
+    __g_armature_check: Dict[int, Optional[int]] = {}
-    SHAPEKEY_NAME = "mmd_sdef_skinning"
+    SHAPEKEY_NAME: str = "mmd_sdef_skinning"
-    MASK_NAME = "mmd_sdef_mask"
+    MASK_NAME: str = "mmd_sdef_mask"
 
-    def __init__(self):
+    def __init__(self) -> None:
         raise NotImplementedError("not allowed")
 
     @classmethod
-    def __init_cache(cls, obj, shapekey):
+    def __init_cache(cls, obj: Object, shapekey: ShapeKey) -> bool:
         key = _hash(obj)
         obj = getattr(obj, "original", obj)
         mod = obj.modifiers.get("mmd_bone_order_override")
         key_armature = _hash(mod.object.pose) if mod and mod.type == "ARMATURE" and mod.object else None
         if key not in cls.g_verts or cls.__g_armature_check.get(key) != key_armature:
+            logger.debug(f"Initializing SDEF cache for {obj.name}")
             cls.g_verts[key] = cls.__find_vertices(obj)
             cls.g_bone_check[key] = {}
             cls.__g_armature_check[key] = key_armature
@@ -49,7 +55,7 @@ class FnSDEF:
         return False
 
     @classmethod
-    def __check_bone_update(cls, obj, bone0, bone1):
+    def __check_bone_update(cls, obj: Object, bone0: PoseBone, bone1: PoseBone) -> bool:
         check = cls.g_bone_check[_hash(obj)]
         key = (_hash(bone0), _hash(bone1))
         if key not in check or (bone0.matrix, bone1.matrix) != check[key]:
@@ -58,17 +64,18 @@ class FnSDEF:
         return False
 
     @classmethod
-    def mute_sdef_set(cls, obj, mute):
+    def mute_sdef_set(cls, obj: Object, mute: bool) -> None:
         key_blocks = getattr(obj.data.shape_keys, "key_blocks", ())
         if cls.SHAPEKEY_NAME in key_blocks:
             shapekey = key_blocks[cls.SHAPEKEY_NAME]
             shapekey.mute = mute
             if cls.has_sdef_data(obj):
+                logger.debug(f"Setting SDEF mute state to {mute} for {obj.name}")
                 cls.__init_cache(obj, shapekey)
                 cls.__sdef_muted(obj, shapekey)
 
     @classmethod
-    def __sdef_muted(cls, obj, shapekey):
+    def __sdef_muted(cls, obj: Object, shapekey: ShapeKey) -> bool:
         mute = shapekey.mute
         if mute != cls.g_bone_check[_hash(obj)].get("sdef_mute"):
             mod = obj.modifiers.get("mmd_bone_order_override")
@@ -80,10 +87,11 @@ class FnSDEF:
                 mod.invert_vertex_group = True
                 shapekey.vertex_group = cls.MASK_NAME
             cls.g_bone_check[_hash(obj)]["sdef_mute"] = mute
+            logger.debug(f"SDEF mute state updated to {mute} for {obj.name}")
         return mute
 
     @staticmethod
-    def has_sdef_data(obj):
+    def has_sdef_data(obj: Object) -> bool:
         mod = obj.modifiers.get("mmd_bone_order_override")
         if mod and mod.type == "ARMATURE" and mod.object:
             kb = getattr(obj.data.shape_keys, "key_blocks", None)
@@ -91,18 +99,21 @@ class FnSDEF:
         return False
 
     @classmethod
-    def __find_vertices(cls, obj):
+    def __find_vertices(cls, obj: Object) -> Dict[Tuple[int, int], Tuple[PoseBone, PoseBone, List[Tuple[int, float, float, Vector, Vector, Vector]], List[int]]]:
         if not cls.has_sdef_data(obj):
             return {}
 
-        vertices = {}
+        vertices: Dict[Tuple[int, int], Tuple[PoseBone, PoseBone, List[Tuple[int, float, float, Vector, Vector, Vector]], List[int]]] = {}
         pose_bones = obj.modifiers.get("mmd_bone_order_override").object.pose.bones
-        bone_map = {g.index: pose_bones[g.name] for g in obj.vertex_groups if g.name in pose_bones}
+        bone_map: Dict[int, PoseBone] = {g.index: pose_bones[g.name] for g in obj.vertex_groups if g.name in pose_bones}
         sdef_c = obj.data.shape_keys.key_blocks["mmd_sdef_c"].data
         sdef_r0 = obj.data.shape_keys.key_blocks["mmd_sdef_r0"].data
         sdef_r1 = obj.data.shape_keys.key_blocks["mmd_sdef_r1"].data
         vd = obj.data.vertices
 
+        logger.debug(f"Finding SDEF vertices for {obj.name}")
+        vertex_count = 0
+
         for i in range(len(sdef_c)):
             if vd[i].co != sdef_c[i].co:
                 bgs = [g for g in vd[i].groups if g.group in bone_map and g.weight]  # bone groups
@@ -125,16 +136,19 @@ class FnSDEF:
                         vertices[key] = (bone_map[bgs[0].group], bone_map[bgs[1].group], [], [])
                     vertices[key][2].append((i, w0, w1, vd[i].co - c, (c + r0) / 2, (c + r1) / 2))
                     vertices[key][3].append(i)
+                    vertex_count += 1
+
+        logger.debug(f"Found {vertex_count} SDEF vertices in {obj.name}")
         return vertices
 
     @classmethod
-    def driver_function_wrap(cls, obj_name, bulk_update, use_skip, use_scale):
+    def driver_function_wrap(cls, obj_name: str, bulk_update: bool, use_skip: bool, use_scale: bool) -> float:
         obj = bpy.data.objects[obj_name]
         shapekey = obj.data.shape_keys.key_blocks[cls.SHAPEKEY_NAME]
         return cls.driver_function(shapekey, obj_name, bulk_update, use_skip, use_scale)
 
     @classmethod
-    def driver_function(cls, shapekey, obj_name, bulk_update, use_skip, use_scale):
+    def driver_function(cls, shapekey: ShapeKey, obj_name: str, bulk_update: bool, use_skip: bool, use_scale: bool) -> float:
         obj = bpy.data.objects[obj_name]
         if getattr(shapekey.id_data, "is_evaluated", False):
             # For Blender 2.8x, we should use evaluated object, and the only reference is the "obj" variable of SDEF driver
@@ -206,11 +220,11 @@ class FnSDEF:
                         rot1 = -rot1
                     s0, s1 = mat0.to_scale(), mat1.to_scale()
 
-                    def scale(mat_rot, w0, w1):
+                    def scale(mat_rot: Matrix, w0: float, w1: float) -> Matrix:
                         s = s0 * w0 + s1 * w1
                         return mat_rot @ Matrix([(s[0], 0, 0), (0, s[1], 0), (0, 0, s[2])])
 
-                    def offset(mat_rot, pos_c, vid):
+                    def offset(mat_rot: Matrix, pos_c: Vector, vid: int) -> Vector:
                         delta = sum(((key.data[vid].co - key.relative_key.data[vid].co) * key.value for key in key_blocks), Vector())  # assuming key.vertex_group = ''
                         return (mat_rot @ (pos_c + delta)) - delta
 
@@ -233,16 +247,19 @@ class FnSDEF:
         return 1.0  # shapkey value
 
     @classmethod
-    def register_driver_function(cls):
+    def register_driver_function(cls) -> None:
+        """Register driver functions in Blender's driver namespace."""
         if "mmd_sdef_driver" not in bpy.app.driver_namespace:
+            logger.debug("Registering SDEF driver function")
             bpy.app.driver_namespace["mmd_sdef_driver"] = cls.driver_function
         if "mmd_sdef_driver_wrap" not in bpy.app.driver_namespace:
+            logger.debug("Registering SDEF driver wrapper function")
             bpy.app.driver_namespace["mmd_sdef_driver_wrap"] = cls.driver_function_wrap
 
-    BENCH_LOOP = 10
+    BENCH_LOOP: int = 10
 
     @classmethod
-    def __get_benchmark_result(cls, obj, shapkey, use_scale, use_skip):
+    def __get_benchmark_result(cls, obj: Object, shapkey: ShapeKey, use_scale: bool, use_skip: bool) -> bool:
         # warmed up
         cls.driver_function(shapkey, obj.name, bulk_update=True, use_skip=False, use_scale=use_scale)
         cls.driver_function(shapkey, obj.name, bulk_update=False, use_skip=False, use_scale=use_scale)
@@ -256,14 +273,15 @@ class FnSDEF:
             cls.driver_function(shapkey, obj.name, bulk_update=True, use_skip=False, use_scale=use_scale)
         bulk_time = time.time() - t
         result = default_time > bulk_time
-        logging.info("FnSDEF:benchmark: default %.4f vs bulk_update %.4f => bulk_update=%s", default_time, bulk_time, result)
+        logger.info(f"SDEF benchmark for {obj.name}: default {default_time:.4f}s vs bulk_update {bulk_time:.4f}s => bulk_update={result}")
         return result
 
     @classmethod
-    def bind(cls, obj, bulk_update=None, use_skip=True, use_scale=False):
+    def bind(cls, obj: Object, bulk_update: Optional[bool] = None, use_skip: bool = True, use_scale: bool = False) -> bool:
         # Unbind first
         cls.unbind(obj)
         if not cls.has_sdef_data(obj):
+            logger.debug(f"Object {obj.name} does not have SDEF data")
             return False
         # Create the shapekey for the driver
         shapekey = obj.shape_key_add(name=cls.SHAPEKEY_NAME, from_mix=False)
@@ -294,32 +312,38 @@ class FnSDEF:
         f.driver.use_self = True
         param = (bulk_update, use_skip, use_scale)
         f.driver.expression = "mmd_sdef_driver(self, obj, bulk_update={}, use_skip={}, use_scale={})".format(*param)
+        logger.info(f"Successfully bound SDEF to {obj.name} with bulk_update={bulk_update}, use_skip={use_skip}, use_scale={use_scale}")
         return True
 
     @classmethod
-    def unbind(cls, obj):
+    def unbind(cls, obj: Object) -> None:
         if obj.data.shape_keys:
             if cls.SHAPEKEY_NAME in obj.data.shape_keys.key_blocks:
+                logger.debug(f"Removing SDEF shape key from {obj.name}")
                 FnObject.mesh_remove_shape_key(obj, obj.data.shape_keys.key_blocks[cls.SHAPEKEY_NAME])
         for mod in obj.modifiers:
             if mod.type == "ARMATURE" and mod.vertex_group == cls.MASK_NAME:
+                logger.debug(f"Clearing SDEF vertex group from modifier in {obj.name}")
                 mod.vertex_group = ""
                 mod.invert_vertex_group = False
                 break
         if cls.MASK_NAME in obj.vertex_groups:
+            logger.debug(f"Removing SDEF vertex group from {obj.name}")
             obj.vertex_groups.remove(obj.vertex_groups[cls.MASK_NAME])
         cls.clear_cache(obj)
 
     @classmethod
-    def clear_cache(cls, obj=None, unused_only=False):
+    def clear_cache(cls, obj: Optional[Object] = None, unused_only: bool = False) -> None:
         if unused_only:
             valid_keys = set(_hash(i) for i in bpy.data.objects if i.type == "MESH" and i != obj)
-            for key in cls.g_verts.keys() - valid_keys:
+            removed_keys = cls.g_verts.keys() - valid_keys
+            for key in removed_keys:
                 del cls.g_verts[key]
             for key in cls.g_shapekey_data.keys() - cls.g_verts.keys():
                 del cls.g_shapekey_data[key]
             for key in cls.g_bone_check.keys() - cls.g_verts.keys():
                 del cls.g_bone_check[key]
+            logger.debug(f"Cleared {len(removed_keys)} unused SDEF cache entries")
         elif obj:
             key = _hash(obj)
             if key in cls.g_verts:
@@ -328,7 +352,9 @@ class FnSDEF:
                 del cls.g_shapekey_data[key]
             if key in cls.g_bone_check:
                 del cls.g_bone_check[key]
+            logger.debug(f"Cleared SDEF cache for {obj.name}")
         else:
+            logger.debug("Cleared all SDEF cache")
             cls.g_verts = {}
             cls.g_bone_check = {}
             cls.g_shapekey_data = {}

core/mmd/core/shader.py

@@ -5,25 +5,33 @@
 # Neoneko has modified this file to work with Avatar Toolkit and may of made changes or improvements.
 # MMD Tools is licensed under the terms of the GNU General Public License version 3 (GPLv3) same as Avatar Toolkit.
 
-from typing import Optional, Tuple, cast
+from typing import Optional, Tuple, cast, List, Dict, Any, Union
 import bpy
+from bpy.types import (
+    ShaderNodeTree, 
+    ShaderNode, 
+    NodeGroupInput, 
+    NodeGroupOutput, 
+    Material
+)
+from ....core.logging_setup import logger
 
 
 class _NodeTreeUtils:
-    def __init__(self, shader: bpy.types.ShaderNodeTree):
+    def __init__(self, shader: ShaderNodeTree):
         self.shader = shader
-        self.nodes: bpy.types.bpy_prop_collection[bpy.types.ShaderNode] = shader.nodes  # type: ignore
+        self.nodes: bpy.types.bpy_prop_collection[ShaderNode] = shader.nodes  # type: ignore
         self.links = shader.links
 
-    def _find_node(self, node_type: str) -> Optional[bpy.types.ShaderNode]:
+    def _find_node(self, node_type: str) -> Optional[ShaderNode]:
         return next((n for n in self.nodes if n.bl_idname == node_type), None)
 
-    def new_node(self, idname: str, pos: Tuple[int, int]) -> bpy.types.ShaderNode:
+    def new_node(self, idname: str, pos: Tuple[int, int]) -> ShaderNode:
-        node: bpy.types.ShaderNode = self.nodes.new(idname)
+        node: ShaderNode = self.nodes.new(idname)
         node.location = (pos[0] * 210, pos[1] * 220)
         return node
 
-    def new_math_node(self, operation, pos, value1=None, value2=None):
+    def new_math_node(self, operation: str, pos: Tuple[int, int], value1: Optional[float] = None, value2: Optional[float] = None) -> ShaderNode:
         node = self.new_node("ShaderNodeMath", pos)
         node.operation = operation
         if value1 is not None:
@@ -32,7 +40,7 @@ class _NodeTreeUtils:
             node.inputs[1].default_value = value2
         return node
 
-    def new_vector_math_node(self, operation, pos, vector1=None, vector2=None):
+    def new_vector_math_node(self, operation: str, pos: Tuple[int, int], vector1: Optional[Tuple[float, float, float, float]] = None, vector2: Optional[Tuple[float, float, float, float]] = None) -> ShaderNode:
         node = self.new_node("ShaderNodeVectorMath", pos)
         node.operation = operation
         if vector1 is not None:
@@ -41,7 +49,7 @@ class _NodeTreeUtils:
             node.inputs[1].default_value = vector2
         return node
 
-    def new_mix_node(self, blend_type, pos, fac=None, color1=None, color2=None):
+    def new_mix_node(self, blend_type: str, pos: Tuple[int, int], fac: Optional[float] = None, color1: Optional[Tuple[float, float, float, float]] = None, color2: Optional[Tuple[float, float, float, float]] = None) -> ShaderNode:
         node = self.new_node("ShaderNodeMixRGB", pos)
         node.blend_type = blend_type
         if fac is not None:
@@ -53,30 +61,30 @@ class _NodeTreeUtils:
         return node
 
 
-SOCKET_TYPE_MAPPING = {"NodeSocketFloatFactor": "NodeSocketFloat"}
+SOCKET_TYPE_MAPPING: Dict[str, str] = {"NodeSocketFloatFactor": "NodeSocketFloat"}
 
-SOCKET_SUBTYPE_MAPPING = {"NodeSocketFloatFactor": "FACTOR"}
+SOCKET_SUBTYPE_MAPPING: Dict[str, str] = {"NodeSocketFloatFactor": "FACTOR"}
 
 
 class _NodeGroupUtils(_NodeTreeUtils):
-    def __init__(self, shader: bpy.types.ShaderNodeTree):
+    def __init__(self, shader: ShaderNodeTree):
         super().__init__(shader)
-        self.__node_input: Optional[bpy.types.NodeGroupInput] = None
+        self.__node_input: Optional[NodeGroupInput] = None
-        self.__node_output: Optional[bpy.types.NodeGroupOutput] = None
+        self.__node_output: Optional[NodeGroupOutput] = None
 
     @property
-    def node_input(self) -> bpy.types.NodeGroupInput:
+    def node_input(self) -> NodeGroupInput:
         if not self.__node_input:
-            self.__node_input = cast(bpy.types.NodeGroupInput, self._find_node("NodeGroupInput") or self.new_node("NodeGroupInput", (-2, 0)))
+            self.__node_input = cast(NodeGroupInput, self._find_node("NodeGroupInput") or self.new_node("NodeGroupInput", (-2, 0)))
         return self.__node_input
 
     @property
-    def node_output(self) -> bpy.types.NodeGroupOutput:
+    def node_output(self) -> NodeGroupOutput:
         if not self.__node_output:
-            self.__node_output = cast(bpy.types.NodeGroupOutput, self._find_node("NodeGroupOutput") or self.new_node("NodeGroupOutput", (2, 0)))
+            self.__node_output = cast(NodeGroupOutput, self._find_node("NodeGroupOutput") or self.new_node("NodeGroupOutput", (2, 0)))
         return self.__node_output
 
-    def hide_nodes(self, hide_sockets=True):
+    def hide_nodes(self, hide_sockets: bool = True) -> None:
         skip_nodes = {self.__node_input, self.__node_output}
         for n in (x for x in self.nodes if x not in skip_nodes):
             n.hide = True
@@ -87,15 +95,15 @@ class _NodeGroupUtils(_NodeTreeUtils):
             for s in n.outputs:
                 s.hide = not s.is_linked
 
-    def new_input_socket(self, io_name, socket, default_val=None, min_max=None, socket_type=None):
+    def new_input_socket(self, io_name: str, socket: Optional[bpy.types.NodeSocket], default_val: Optional[Union[float, Tuple[float, float, float, float]]] = None, min_max: Optional[Tuple[float, float]] = None, socket_type: Optional[str] = None) -> None:
         self.__new_io("INPUT", self.node_input.outputs, io_name, socket, default_val, min_max, socket_type)
 
-    def new_output_socket(self, io_name, socket, default_val=None, min_max=None, socket_type=None):
+    def new_output_socket(self, io_name: str, socket: Optional[bpy.types.NodeSocket], default_val: Optional[Union[float, Tuple[float, float, float, float]]] = None, min_max: Optional[Tuple[float, float]] = None, socket_type: Optional[str] = None) -> None:
         self.__new_io("OUTPUT", self.node_output.inputs, io_name, socket, default_val, min_max, socket_type)
 
-    def __new_io(self, in_out, io_sockets, io_name, socket, default_val=None, min_max=None, socket_type=None):
+    def __new_io(self, in_out: str, io_sockets: bpy.types.bpy_prop_collection, io_name: str, socket: Optional[bpy.types.NodeSocket], default_val: Optional[Union[float, Tuple[float, float, float, float]]] = None, min_max: Optional[Tuple[float, float]] = None, socket_type: Optional[str] = None) -> None:
         if io_name not in io_sockets:
-            idname = socket_type or socket.bl_idname
+            idname = socket_type or (socket.bl_idname if socket else "NodeSocketFloat")
             interface_socket = self.shader.interface.new_socket(name=io_name, in_out=in_out, socket_type=SOCKET_TYPE_MAPPING.get(idname, idname))
             if idname in SOCKET_SUBTYPE_MAPPING:
                 interface_socket.subtype = SOCKET_SUBTYPE_MAPPING.get(idname, "")
@@ -114,14 +122,18 @@ class _NodeGroupUtils(_NodeTreeUtils):
 
 class _MaterialMorph:
     @classmethod
-    def update_morph_inputs(cls, material, morph):
+    def update_morph_inputs(cls, material: Optional[Material], morph: Any) -> None:
+        """Update material morph inputs based on morph data"""
         if material and material.node_tree and morph.name in material.node_tree.nodes:
+            logger.debug(f"Updating morph inputs for {morph.name} in {material.name}")
             cls.__update_node_inputs(material.node_tree.nodes[morph.name], morph)
             cls.update_morph_inputs(bpy.data.materials.get("mmd_edge." + material.name, None), morph)
 
     @classmethod
-    def setup_morph_nodes(cls, material, morphs):
+    def setup_morph_nodes(cls, material: Material, morphs: List[Any]) -> List[ShaderNode]:
+        """Set up morph nodes for a material"""
         node, nodes = None, []
+        logger.debug(f"Setting up {len(morphs)} morph nodes for {material.name}")
         for m in morphs:
             node = cls.__morph_node_add(material, m, node)
             nodes.append(node)
@@ -137,23 +149,25 @@ class _MaterialMorph:
         return nodes
 
     @classmethod
-    def reset_morph_links(cls, node):
+    def reset_morph_links(cls, node: ShaderNode) -> None:
+        """Reset morph links for a node"""
+        logger.debug(f"Resetting morph links for {node.name}")
         cls.__update_morph_links(node, reset=True)
 
     @classmethod
-    def __update_morph_links(cls, node, reset=False):
+    def __update_morph_links(cls, node: ShaderNode, reset: bool = False) -> None:
         nodes, links = node.id_data.nodes, node.id_data.links
         if reset:
             if any(l.from_node.name.startswith("mmd_bind") for i in node.inputs for l in i.links):
                 return
 
-            def __init_link(socket_morph, socket_shader):
+            def __init_link(socket_morph: bpy.types.NodeSocket, socket_shader: Optional[bpy.types.NodeSocket]) -> None:
                 if socket_shader and socket_morph.is_linked:
                     links.new(socket_morph.links[0].from_socket, socket_shader)
 
         else:
 
-            def __init_link(socket_morph, socket_shader):
+            def __init_link(socket_morph: bpy.types.NodeSocket, socket_shader: Optional[bpy.types.NodeSocket]) -> None:
                 if socket_shader:
                     if socket_shader.is_linked:
                         links.new(socket_shader.links[0].from_socket, socket_morph)
@@ -178,7 +192,8 @@ class _MaterialMorph:
             __init_link(node.inputs["Edge1 A"], shader.inputs["Alpha"])
 
     @classmethod
-    def __update_node_inputs(cls, node, morph):
+    def __update_node_inputs(cls, node: ShaderNode, morph: Any) -> None:
+        """Update node inputs based on morph data"""
         node.inputs["Ambient2"].default_value[:3] = morph.ambient_color[:3]
         node.inputs["Diffuse2"].default_value[:3] = morph.diffuse_color[:3]
         node.inputs["Specular2"].default_value[:3] = morph.specular_color[:3]
@@ -196,7 +211,8 @@ class _MaterialMorph:
         node.inputs["Sphere2 A"].default_value = morph.sphere_texture_factor[3]
 
     @classmethod
-    def __morph_node_add(cls, material, morph, prev_node):
+    def __morph_node_add(cls, material: Material, morph: Optional[Any], prev_node: Optional[ShaderNode]) -> Optional[ShaderNode]:
+        """Add a morph node to a material"""
         nodes, links = material.node_tree.nodes, material.node_tree.links
 
         shader = nodes.get("mmd_shader", None)
@@ -221,8 +237,9 @@ class _MaterialMorph:
             return node
         # connect last node to shader
         if shader:
+            logger.debug(f"Connecting last node to shader for {material.name}")
 
-            def __soft_link(socket_out, socket_in):
+            def __soft_link(socket_out: Optional[bpy.types.NodeSocket], socket_in: Optional[bpy.types.NodeSocket]) -> None:
                 if socket_out and socket_in:
                     links.new(socket_out, socket_in)
 
@@ -244,12 +261,14 @@ class _MaterialMorph:
         return shader
 
     @classmethod
-    def __get_shader(cls, morph_type):
+    def __get_shader(cls, morph_type: str) -> ShaderNodeTree:
+        """Get or create a shader node group for the specified morph type"""
         group_name = "MMDMorph" + morph_type
         shader = bpy.data.node_groups.get(group_name, None) or bpy.data.node_groups.new(name=group_name, type="ShaderNodeTree")
         if len(shader.nodes):
             return shader
 
+        logger.info(f"Creating new shader node group: {group_name}")
         ng = _NodeGroupUtils(shader)
         links = ng.links
 
@@ -260,7 +279,7 @@ class _MaterialMorph:
         ng.new_input_socket("Fac", None, 0, socket_type="NodeSocketFloat")
         ng.new_node("NodeGroupOutput", (3, 0))
 
-        def __blend_color_add(id_name, pos, tag=""):
+        def __blend_color_add(id_name: str, pos: Tuple[int, int], tag: str = "") -> ShaderNode:
             # MA_RAMP_MULT: ColorMul = Color1 * (Fac * Color2 + (1 - Fac))
             # MA_RAMP_ADD:  ColorAdd = Color1 + Fac * Color2
             # https://github.com/blender/blender/blob/594f47ecd2d5367ca936cf6fc6ec8168c2b360d0/source/blender/blenkernel/intern/material.c#L1400
@@ -271,7 +290,7 @@ class _MaterialMorph:
             ng.new_output_socket(id_name + tag, node_mix.outputs["Color"])
             return node_mix
 
-        def __blend_tex_color(id_name, pos, node_tex_rgb, node_tex_a_output):
+        def __blend_tex_color(id_name: str, pos: Tuple[int, int], node_tex_rgb: ShaderNode, node_tex_a_output: bpy.types.NodeSocket) -> None:
             # Tex Color = tex_rgb * tex_a + (1 - tex_a)
             # : tex_rgb = TexRGB * ColorMul + ColorAdd
             # : tex_a = TexA * ValueMul + ValueAdd
@@ -294,7 +313,7 @@ class _MaterialMorph:
                 ng.new_output_socket(id_name + " Tex", node_add.outputs[0], socket_type="NodeSocketColor")
                 ng.new_output_socket(id_name + " Tex Add", node_scale.outputs[0], socket_type="NodeSocketColor")
 
-        def __add_sockets(id_name, input1, input2, output, tag=""):
+        def __add_sockets(id_name: str, input1: bpy.types.NodeSocket, input2: bpy.types.NodeSocket, output: bpy.types.NodeSocket, tag: str = "") -> None:
             ng.new_input_socket(f"{id_name}1{tag}", input1, use_mul)
             ng.new_input_socket(f"{id_name}2{tag}", input2, use_mul)
             ng.new_output_socket(f"{id_name}{tag}", output)
@@ -343,4 +362,5 @@ class _MaterialMorph:
         __blend_tex_color("Sphere", (pos_x + 3, -3.5), sphere_rgb, separate_basea_toona_spherea.outputs[2])
 
         ng.hide_nodes()
+        logger.debug(f"Shader node group {group_name} created successfully")
         return ng.shader