feat: logging cleanup

multi_user/__init__.py

@@ -51,26 +51,26 @@ DEPENDENCIES = {
 }
 
 
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
-
-
 libs = os.path.dirname(os.path.abspath(__file__))+"\\libs\\replication\\replication"
 
 def register():
+    # Setup logging policy
+    logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.INFO)
+    
     if libs not in sys.path:
         sys.path.append(libs)
     
-    environment.setup(DEPENDENCIES,bpy.app.binary_path_python)
-
     try:
-        from . import presence
+        environment.setup(DEPENDENCIES, bpy.app.binary_path_python)
-        from . import operators
-        from . import ui
-        from . import preferences
-        from . import addon_updater_ops
     except ModuleNotFoundError:
-        logger.error("Libraries not installed, try to relaunch blender with admin rights")
+        logging.fatal("Fail to install multi-user dependencies, try to execute blender with admin rights.")
+        return
+        
+    from . import presence
+    from . import operators
+    from . import ui
+    from . import preferences
+    from . import addon_updater_ops
 
     preferences.register()
     addon_updater_ops.register(bl_info)

multi_user/bl_types/bl_curve.py

@@ -27,7 +27,6 @@ from .dump_anything import (Dumper, Loader,
                                   np_load_collection,
                                   np_dump_collection)
 
-logger = logging.getLogger(__name__)
 
 SPLINE_BEZIER_POINT = [
     # "handle_left_type",
@@ -77,7 +76,7 @@ class BlCurve(BlDatablock):
             # Not really working for now...
             # See https://blender.stackexchange.com/questions/7020/create-nurbs-surface-with-python
             if new_spline.type == 'NURBS':
-                logger.error("NURBS not supported.")
+                logging.error("NURBS not supported.")
             #     new_spline.points.add(len(data['splines'][spline]["points"])-1)
             #     for point_index in data['splines'][spline]["points"]:
             #         loader.load(

multi_user/bl_types/bl_datablock.py

@@ -109,7 +109,7 @@ class BlDatablock(ReplicatedDatablock):
         if instance and hasattr(instance, 'uuid'):
            instance.uuid = self.uuid
         
-        self.diff_method = DIFF_BINARY
+        # self.diff_method = DIFF_BINARY
 
     @property
     def instance(self):

multi_user/bl_types/bl_image.py

@@ -28,7 +28,7 @@ def dump_image(image):
     pixels = None
     if image.source == "GENERATED":
         prefs = utils.get_preferences()
-        img_name = "{}.png".format(image.name)
+        img_name = f"{image.name}.png"
         
         # Cache the image on the disk
         image.filepath_raw = os.path.join(prefs.cache_directory, img_name)
@@ -67,7 +67,7 @@ class BlImage(BlDatablock):
         image = target
         prefs = utils.get_preferences()
 
-        img_name = "{}.png".format(image.name)
+        img_name = f"{image.name}.png"
 
         img_path = os.path.join(prefs.cache_directory, img_name)
 

multi_user/bl_types/bl_lattice.py

@@ -21,6 +21,7 @@ import mathutils
 
 from .dump_anything import Dumper, Loader, np_dump_collection, np_load_collection
 from .bl_datablock import BlDatablock
+from ..libs.replication.replication.exception import ContextError
 
 POINT = ['co', 'weight_softbody', 'co_deform']
 
@@ -37,13 +38,17 @@ class BlLattice(BlDatablock):
         return bpy.data.lattices.new(data["name"])
 
     def _load_implementation(self, data, target):
+        if target.is_editmode:
+            raise ContextError("lattice is in edit mode")
+
         loader = Loader()
         loader.load(target, data)
 
         np_load_collection(data['points'], target.points, POINT)
 
     def _dump_implementation(self, data, instance=None):
-        assert(instance)
+        if instance.is_editmode:
+            raise ContextError("lattice is in edit mode")
 
         dumper = Dumper()
         dumper.depth = 1
@@ -61,5 +66,6 @@ class BlLattice(BlDatablock):
         data = dumper.dump(instance)
 
         data['points'] = np_dump_collection(instance.points, POINT)
+
         return data
 

multi_user/bl_types/bl_lightprobe.py

@@ -23,7 +23,6 @@ import logging
 from .dump_anything import Loader, Dumper
 from .bl_datablock import BlDatablock
 
-logger = logging.getLogger(__name__)
 
 class BlLightprobe(BlDatablock):
     bl_id = "lightprobes"
@@ -39,7 +38,7 @@ class BlLightprobe(BlDatablock):
         if bpy.app.version[1] >= 83:
             return bpy.data.lightprobes.new(data["name"], type)
         else:
-            logger.warning("Lightprobe replication only supported since 2.83. See https://developer.blender.org/D6396")
+            logging.warning("Lightprobe replication only supported since 2.83. See https://developer.blender.org/D6396")
 
     def _load_implementation(self, data, target):
         loader = Loader()
@@ -48,7 +47,7 @@ class BlLightprobe(BlDatablock):
     def _dump_implementation(self, data, instance=None):
         assert(instance)
         if bpy.app.version[1] < 83:
-            logger.warning("Lightprobe replication only supported since 2.83. See https://developer.blender.org/D6396")
+            logging.warning("Lightprobe replication only supported since 2.83. See https://developer.blender.org/D6396")
 
         dumper = Dumper()
         dumper.depth = 1

multi_user/bl_types/bl_material.py

@@ -24,7 +24,6 @@ from .. import utils
 from .dump_anything import Loader, Dumper
 from .bl_datablock import BlDatablock
 
-logger = logging.getLogger(__name__)
 
 def load_node(node_data, node_tree):
     """ Load a node into a node_tree from a dict
@@ -46,7 +45,7 @@ def load_node(node_data, node_tree):
             try:
                 target_node.inputs[input].default_value = node_data["inputs"][input]["default_value"]
             except:
-                logger.error("{} not supported, skipping".format(input))
+                logging.error(f"Material {input} parameter not supported, skipping")
 
 
 def load_links(links_data, node_tree):

multi_user/bl_types/bl_mesh.py

@@ -24,9 +24,9 @@ import numpy as np
 
 from .dump_anything import Dumper, Loader, np_load_collection_primitives, np_dump_collection_primitive, np_load_collection, np_dump_collection
 from ..libs.replication.replication.constants import DIFF_BINARY
+from ..libs.replication.replication.exception import ContextError
 from .bl_datablock import BlDatablock
 
-logger = logging.getLogger(__name__)
 
 VERTICE = ['co']
 
@@ -111,7 +111,9 @@ class BlMesh(BlDatablock):
 
     def _dump_implementation(self, data, instance=None):
         assert(instance)
-
+        
+        if instance.is_editmode:
+            raise ContextError("Mesh is in edit mode")
         mesh = instance
 
         dumper = Dumper()

multi_user/bl_types/bl_object.py

@@ -22,8 +22,7 @@ import logging
 
 from .dump_anything import Loader, Dumper
 from .bl_datablock import BlDatablock
-
+from ..libs.replication.replication.exception import ContextError
-logger = logging.getLogger(__name__)
 
 
 def load_pose(target_bone, data):
@@ -80,7 +79,7 @@ class BlObject(BlDatablock):
             if bpy.app.version[1] >= 83:
                 instance = bpy.data.lightprobes[data["data"]]
             else:
-                logger.warning(
+                logging.warning(
                     "Lightprobe replication only supported since 2.83. See https://developer.blender.org/D6396")
         instance = bpy.data.objects.new(data["name"], instance)
         instance.uuid = self.uuid
@@ -126,7 +125,8 @@ class BlObject(BlDatablock):
             target.vertex_groups.clear()
             for vg in data['vertex_groups']:
                 vertex_group = target.vertex_groups.new(name=vg['name'])
-                for vert in vg['vertices']:
+                point_attr =  'vertices' if 'vertices' in vg else 'points'
+                for vert in vg[point_attr]:
                     vertex_group.add(
                         [vert['index']], vert['weight'], 'REPLACE')
 
@@ -154,6 +154,12 @@ class BlObject(BlDatablock):
 
     def _dump_implementation(self, data, instance=None):
         assert(instance)
+        
+        child_data = getattr(instance, 'data', None)
+        
+        if child_data and hasattr(child_data, 'is_editmode') and child_data.is_editmode:
+            raise ContextError("Object is in edit-mode.")
+
         dumper = Dumper()
         dumper.depth = 1
         dumper.include_filter = [
@@ -239,6 +245,7 @@ class BlObject(BlDatablock):
 
         # VERTEx GROUP
         if len(instance.vertex_groups) > 0:
+            points_attr = 'vertices' if isinstance(instance.data, bpy.types.Mesh) else 'points'
             vg_data = []
             for vg in instance.vertex_groups:
                 vg_idx = vg.index
@@ -247,11 +254,11 @@ class BlObject(BlDatablock):
 
                 vertices = []
 
-                for v in instance.data.vertices:
+                for i, v in enumerate(getattr(instance.data, points_attr)):
                     for vg in v.groups:
                         if vg.group == vg_idx:
                             vertices.append({
-                                'index': v.index,
+                                'index': i,
                                 'weight': vg.weight
                             })
 

multi_user/bl_types/bl_scene.py

@@ -126,9 +126,9 @@ class BlScene(BlDatablock):
             data['eevee'] = scene_dumper.dump(instance.eevee)
             data['cycles'] = scene_dumper.dump(instance.cycles)        
             data['view_settings'] = scene_dumper.dump(instance.view_settings)
-            data['view_settings']['curve_mapping'] = scene_dumper.dump(instance.view_settings.curve_mapping)
+           
-            
             if instance.view_settings.use_curve_mapping:
+                data['view_settings']['curve_mapping'] = scene_dumper.dump(instance.view_settings.curve_mapping)
                 scene_dumper.depth = 5
                 scene_dumper.include_filter = [
                     'curves',

multi_user/bl_types/dump_anything.py

@@ -22,7 +22,6 @@ import bpy.types as T
 import mathutils
 import numpy as np
 
-logger = logging.getLogger(__name__)
 
 BPY_TO_NUMPY_TYPES = {
     'FLOAT': np.float,
@@ -48,7 +47,7 @@ def np_load_collection(dikt: dict, collection: bpy.types.CollectionProperty, att
         :type attributes: list
     """
     if not dikt or len(collection) == 0:
-        logger.warning(f'Skipping collection')
+        logging.warning(f'Skipping collection')
         return
 
     if attributes is None:
@@ -62,7 +61,7 @@ def np_load_collection(dikt: dict, collection: bpy.types.CollectionProperty, att
         elif attr_type == 'ENUM':
             np_load_collection_enum(collection, attr, dikt[attr])
         else:
-            logger.error(f"{attr} of type {attr_type} not supported.")
+            logging.error(f"{attr} of type {attr_type} not supported.")
 
 
 def np_dump_collection(collection: bpy.types.CollectionProperty, attributes: list = None) -> dict:
@@ -98,7 +97,7 @@ def np_dump_collection(collection: bpy.types.CollectionProperty, attributes: lis
         elif attr_type == 'ENUM':
             dumped_collection[attr] = np_dump_collection_enum(collection, attr)
         else:
-            logger.error(f"{attr} of type {attr_type} not supported. Only {PRIMITIVE_TYPES} and ENUM supported. Skipping it.")
+            logging.error(f"{attr} of type {attr_type} not supported. Only {PRIMITIVE_TYPES} and ENUM supported. Skipping it.")
 
     return dumped_collection
 
@@ -116,7 +115,7 @@ def np_dump_collection_primitive(collection: bpy.types.CollectionProperty, attri
         :return: numpy byte buffer
     """
     if len(collection) == 0:
-        logger.warning(f'Skipping empty {attribute} attribute')
+        logging.warning(f'Skipping empty {attribute} attribute')
         return {}
 
     attr_infos = collection[0].bl_rna.properties.get(attribute)
@@ -193,7 +192,7 @@ def np_load_collection_primitives(collection: bpy.types.CollectionProperty, attr
         :type sequence: strr
     """
     if len(collection) == 0 or not sequence:
-        logger.warning(f"Skipping loadin {attribute}")
+        logging.warning(f"Skipping loadin {attribute}")
         return
     
     attr_infos = collection[0].bl_rna.properties.get(attribute)
@@ -379,7 +378,7 @@ class Dumper:
                     return False
                 getattr(default, p)
             except AttributeError as err:
-                logger.debug(err)
+                logging.debug(err)
                 return False
             if p.startswith("__"):
                 return False
@@ -489,7 +488,7 @@ class Loader:
             for i in range(len(dump)):
                 element.read()[i] = dump[i]
         except AttributeError as err:
-            logger.debug(err)
+            logging.debug(err)
             if not self.occlude_read_only:
                 raise err
 
@@ -541,7 +540,7 @@ class Loader:
                     _constructor_parameters = [dumped_element[name]
                                               for name in _constructor[1]]
                 except KeyError:
-                    logger.debug("Collection load error, missing parameters.")
+                    logging.debug("Collection load error, missing parameters.")
                     continue  # TODO handle error
 
                 new_element = getattr(element.read(), _constructor[0])(
@@ -623,11 +622,11 @@ class Loader:
         for k in self._ordered_keys(dump.keys()):
             v = dump[k]
             if not hasattr(default.read(), k):
-                logger.debug(f"Load default, skipping {default} : {k}")
+                logging.debug(f"Load default, skipping {default} : {k}")
             try:
                 self._load_any(default.extend(k), v)
             except Exception as err:
-                logger.debug(f"Cannot load {k}: {err}")
+                logging.debug(f"Cannot load {k}: {err}")
 
     @property
     def match_subset_all(self):

multi_user/delayable.py

@@ -22,9 +22,6 @@ import bpy
 from . import operators, presence, utils
 from .libs.replication.replication.constants import FETCHED, RP_COMMON, STATE_INITIAL,STATE_QUITTING, STATE_ACTIVE, STATE_SYNCING, STATE_SRV_SYNC
 
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
-
 
 class Delayable():
     """Delayable task interface
@@ -92,8 +89,7 @@ class ApplyTimer(Timer):
                     try:
                         client.apply(node)
                     except Exception as e:
-                        logger.error(
+                        logging.error(f"Fail to apply {node_ref.uuid}: {e}")
-                            "fail to apply {}: {}".format(node_ref.uuid, e))
 
 
 class DynamicRightSelectTimer(Timer):
@@ -164,7 +160,7 @@ class DynamicRightSelectTimer(Timer):
                         }
 
                         session.update_user_metadata(user_metadata)
-                        logger.info("Update selection")
+                        logging.debug("Update selection")
 
                         # Fix deselection until right managment refactoring (with Roles concepts)
                         if len(current_selection) == 0 and self._right_strategy == RP_COMMON:

multi_user/environment.py

@@ -23,8 +23,6 @@ import subprocess
 import sys
 from pathlib import Path
 
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
 
 THIRD_PARTY = os.path.join(os.path.dirname(os.path.abspath(__file__)), "libs")
 DEFAULT_CACHE_DIR = os.path.join(os.path.dirname(os.path.abspath(__file__)), "cache")
@@ -49,8 +47,9 @@ def install_pip():
 
 
 def install_package(name):
-    subprocess.run([str(PYTHON_PATH), "-m", "pip", "install",
+    logging.debug(f"Using {PYTHON_PATH} for installation")
-                    name], cwd=SUBPROCESS_DIR)
+    subprocess.run([str(PYTHON_PATH), "-m", "pip", "install", name])
+
 
 def check_dir(dir):
     if not os.path.exists(dir):
@@ -68,3 +67,4 @@ def setup(dependencies, python_path):
     for module_name, package_name in dependencies:
         if not module_can_be_imported(module_name):
             install_package(package_name)
+            module_can_be_imported(package_name)

multi_user/operators.py

@@ -39,8 +39,6 @@ from .libs.replication.replication.data import ReplicatedDataFactory
 from .libs.replication.replication.exception import NonAuthorizedOperationError
 from .libs.replication.replication.interface import Session
 
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
 
 client = None
 delayables = []
@@ -91,7 +89,7 @@ class SessionStartOperator(bpy.types.Operator):
         # init the factory with supported types
         for type in bl_types.types_to_register():
             type_module = getattr(bl_types, type)
-            type_impl_name = "Bl{}".format(type.split('_')[1].capitalize())
+            type_impl_name = f"Bl{type.split('_')[1].capitalize()}"
             type_module_class = getattr(type_module, type_impl_name)
 
             supported_bl_types.append(type_module_class.bl_id)
@@ -135,7 +133,7 @@ class SessionStartOperator(bpy.types.Operator):
                 )
             except Exception as e:
                 self.report({'ERROR'}, repr(e))
-                logger.error(f"Error: {e}")
+                logging.error(f"Error: {e}")
             finally:
                 runtime_settings.is_admin = True
 
@@ -153,7 +151,7 @@ class SessionStartOperator(bpy.types.Operator):
                 )
             except Exception as e:
                 self.report({'ERROR'}, repr(e))
-                logger.error(f"Error: {e}")
+                logging.error(f"Error: {e}")
             finally:
                 runtime_settings.is_admin = False
 
@@ -177,7 +175,7 @@ class SessionStartOperator(bpy.types.Operator):
 
         self.report(
             {'INFO'},
-            "connexion on tcp://{}:{}".format(settings.ip, settings.port))
+            f"connecting to tcp://{settings.ip}:{settings.port}")
         return {"FINISHED"}
 
 
@@ -467,8 +465,7 @@ class ApplyArmatureOperator(bpy.types.Operator):
                         try:
                             client.apply(node)
                         except Exception as e:
-                            logger.error(
+                            logging.error("Dail to apply armature: {e}")
-                                "fail to apply {}: {}".format(node_ref.uuid, e))
 
         return {'PASS_THROUGH'}
 
@@ -520,40 +517,6 @@ def update_client_frame(scene):
             'frame_current': scene.frame_current
         })
 
-@persistent
-def depsgraph_evaluation(scene):
-    if client and client.state['STATE'] == STATE_ACTIVE:
-        context = bpy.context
-        blender_depsgraph = bpy.context.view_layer.depsgraph
-        dependency_updates = [u for u in blender_depsgraph.updates]
-        session_infos = utils.get_preferences()
-
-        # NOTE: maybe we don't need to check each update but only the first
-
-        for update in reversed(dependency_updates):
-            # Is the object tracked ?
-            if update.id.uuid:
-                # Retrieve local version
-                node = client.get(update.id.uuid)
-                
-                # Check our right on this update:
-                #   - if its ours or ( under common and diff), launch the
-                # update process
-                #   - if its to someone else, ignore the update (go deeper ?)
-                if node.owner == session_infos.username:
-                    # Avoid slow geometry update
-                    if 'EDIT' in context.mode:
-                        break
-                    logger.error("UPDATE: MODIFIFY {}".format(type(update.id)))
-                    # client.commit(node.uuid)
-                    # client.push(node.uuid)
-                else:
-                    # Distant update
-                    continue
-            # else:
-            #     # New items !
-            #     logger.error("UPDATE: ADD")C.obj  
-
 
 def register():
     from bpy.utils import register_class
@@ -565,8 +528,6 @@ def register():
 
     bpy.app.handlers.frame_change_pre.append(update_client_frame)
 
-    # bpy.app.handlers.depsgraph_update_post.append(depsgraph_evaluation)
-
 
 def unregister():
     global client
@@ -584,8 +545,6 @@ def unregister():
 
     bpy.app.handlers.frame_change_pre.remove(update_client_frame)
 
-    # bpy.app.handlers.depsgraph_update_post.remove(depsgraph_evaluation)
-
 
 if __name__ == "__main__":
     register()

multi_user/preferences.py

@@ -23,7 +23,6 @@ import string
 from . import utils, bl_types, environment, addon_updater_ops, presence
 from .libs.replication.replication.constants import  RP_COMMON
 
-logger = logging.getLogger(__name__)
 
 def randomColor():
     """Generate a random color """
@@ -117,6 +116,18 @@ class SessionPrefs(bpy.types.AddonPreferences):
         ],
         default='CONFIG'
     )
+    # WIP
+    logging_level: bpy.props.EnumProperty(
+        name="Log level",
+        description="Log verbosity level",
+        items=[
+            ('ERROR', "error", "show only errors"),
+            ('WARNING', "warning", "only show warnings and errors"),
+            ('INFO', "info", "default level"),
+            ('DEBUG', "debug", "show all logs"),
+        ],
+        default='INFO'
+    )
     conf_session_identity_expanded: bpy.props.BoolProperty(
         name="Identity",
         description="Identity",
@@ -260,7 +271,7 @@ class SessionPrefs(bpy.types.AddonPreferences):
             new_db = self.supported_datablocks.add()
 
             type_module = getattr(bl_types, type)
-            type_impl_name = "Bl{}".format(type.split('_')[1].capitalize())
+            type_impl_name = f"Bl{type.split('_')[1].capitalize()}"
             type_module_class = getattr(type_module, type_impl_name)
 
             new_db.name = type_impl_name
@@ -370,7 +381,7 @@ def register():
 
     prefs = bpy.context.preferences.addons[__package__].preferences
     if len(prefs.supported_datablocks) == 0:
-        logger.info('Generating bl_types preferences')
+        logging.debug('Generating bl_types preferences')
         prefs.generate_supported_types()
 
 

multi_user/presence.py

@@ -32,8 +32,6 @@ from . import utils
 
 renderer = None
 
-logger = logging.getLogger(__name__)
-
 
 def view3d_find():
     """ Find the first 'VIEW_3D' windows found in areas
@@ -210,7 +208,7 @@ class DrawFactory(object):
 
     def flush_selection(self, user=None):
         key_to_remove = []
-        select_key = "{}_select".format(user) if user else "select"
+        select_key = f"{user}_select" if user else "select"
         for k in self.d3d_items.keys():
 
             if select_key in k:
@@ -237,7 +235,7 @@ class DrawFactory(object):
             self.flush_selection(client_id)
 
             for select_ob in client_selection:
-                drawable_key = "{}_select_{}".format(client_id, select_ob)
+                drawable_key = f"{client_id}_select_{select_ob}"
                
                 ob = utils.find_from_attr("uuid", select_ob, bpy.data.objects)
                 if not ob:
@@ -313,7 +311,7 @@ class DrawFactory(object):
                     self.d2d_items[client_id] = (position[1], client_id, color)
 
                 except Exception as e:
-                    logger.error("Draw client exception {}".format(e))
+                    logging.error(f"Draw client exception: {e}")
 
     def draw3d_callback(self):
         bgl.glLineWidth(1.5)
@@ -327,7 +325,7 @@ class DrawFactory(object):
                 shader.uniform_float("color", color)
                 batch.draw(shader)
         except Exception:
-            logger.error("3D Exception")
+            logging.error("3D Exception")
 
     def draw2d_callback(self):
         for position, font, color in self.d2d_items.values():
@@ -341,7 +339,7 @@ class DrawFactory(object):
                     blf.draw(0,  font)
 
             except Exception:
-                logger.error("2D EXCEPTION")
+                logging.error("2D EXCEPTION")
 
 
 def register():

multi_user/ui.py

@@ -48,10 +48,9 @@ def printProgressBar (iteration, total, prefix = '', suffix = '', decimals = 1,
     From here:    
     https://gist.github.com/greenstick/b23e475d2bfdc3a82e34eaa1f6781ee4
     """
-    percent = ("{0:." + str(decimals) + "f}").format(100 * (iteration / float(total)))
     filledLength = int(length * iteration // total)
     bar = fill * filledLength + fill_empty * (length - filledLength)
-    return '{} |{}| {}/{}{}'.format(prefix, bar, iteration,total, suffix)
+    return f"{prefix} |{bar}| {iteration}/{total}{suffix}"
 
 def get_state_str(state):
     state_str = 'UNKNOWN'
@@ -429,7 +428,7 @@ def draw_property(context, parent, property_uuid, level=0):
 
     detail_item_box.label(text="",
                           icon=settings.supported_datablocks[item.str_type].icon)
-    detail_item_box.label(text="{} ".format(name))
+    detail_item_box.label(text=f"{name}")
 
     # Operations
 

multi_user/utils.py

@@ -29,9 +29,6 @@ import mathutils
 
 from . import environment, presence
 
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
-
 
 def find_from_attr(attr_name, attr_value, list):
     for item in list: