diff --git a/netbox_branching/models/branches.py b/netbox_branching/models/branches.py index 1779157..b337ab1 100644 --- a/netbox_branching/models/branches.py +++ b/netbox_branching/models/branches.py @@ -240,15 +240,22 @@ def sync(self, user, commit=True): if not self.ready: raise Exception(f"Branch {self} is not ready to sync") + # Retrieve unsynced changes before we update the Branch's status + if changes := self.get_unsynced_changes().order_by('time'): + logger.debug(f"Found {len(changes)} changes to sync") + else: + logger.info(f"No changes found; aborting.") + return + # Update Branch status + logger.debug(f"Setting branch status to {BranchStatusChoices.SYNCING}") Branch.objects.filter(pk=self.pk).update(status=BranchStatusChoices.SYNCING) try: with activate_branch(self): with transaction.atomic(using=self.connection_name): # Apply each change from the main schema - for change in self.get_unsynced_changes().order_by('time'): - logger.debug(f'Applying change: {change}') + for change in changes: change.apply(using=self.connection_name) if not commit: raise AbortTransaction() @@ -260,9 +267,13 @@ def sync(self, user, commit=True): raise e # Record the branch's last_synced time & update its status + logger.debug(f"Setting branch status to {BranchStatusChoices.READY}") self.last_sync = timezone.now() self.status = BranchStatusChoices.READY self.save() + + # Record a branch event for the sync + logger.debug(f"Recording branch event: {BranchEventTypeChoices.SYNCED}") BranchEvent.objects.create(branch=self, user=user, type=BranchEventTypeChoices.SYNCED) # Emit branch_synced signal @@ -284,9 +295,14 @@ def merge(self, user, commit=True): raise Exception(f"Branch {self} is not ready to merge") # Retrieve staged changes before we update the Branch's status - changes = self.get_unmerged_changes().order_by('time') + if changes := self.get_unmerged_changes().order_by('time'): + logger.debug(f"Found {len(changes)} changes to merge") + else: + logger.info(f"No changes found; aborting.") + return # Update Branch status + logger.debug(f"Setting branch status to {BranchStatusChoices.MERGING}") Branch.objects.filter(pk=self.pk).update(status=BranchStatusChoices.MERGING) # Create a dummy request for the event_tracking() context manager @@ -301,7 +317,6 @@ def merge(self, user, commit=True): # Apply each change from the Branch for change in changes: with event_tracking(request): - logger.debug(f'Applying change: {change}') request.id = change.request_id request.user = change.user change.apply(using=DEFAULT_DB_ALIAS) @@ -316,10 +331,14 @@ def merge(self, user, commit=True): raise e # Update the Branch's status to "merged" + logger.debug(f"Setting branch status to {BranchStatusChoices.MERGED}") self.status = BranchStatusChoices.MERGED self.merged_time = timezone.now() self.merged_by = user self.save() + + # Record a branch event for the merge + logger.debug(f"Recording branch event: {BranchEventTypeChoices.MERGED}") BranchEvent.objects.create(branch=self, user=user, type=BranchEventTypeChoices.MERGED) # Emit branch_merged signal @@ -344,9 +363,14 @@ def revert(self, user, commit=True): raise Exception(f"Only merged branches can be reverted.") # Retrieve applied changes before we update the Branch's status - changes = self.get_changes().order_by('-time') + if changes := self.get_changes().order_by('-time'): + logger.debug(f"Found {len(changes)} changes to revert") + else: + logger.info(f"No changes found; aborting.") + return # Update Branch status + logger.debug(f"Setting branch status to {BranchStatusChoices.REVERTING}") Branch.objects.filter(pk=self.pk).update(status=BranchStatusChoices.REVERTING) # Create a dummy request for the event_tracking() context manager @@ -361,7 +385,6 @@ def revert(self, user, commit=True): # Undo each change from the Branch for change in changes: with event_tracking(request): - logger.debug(f'Undoing change: {change}') request.id = change.request_id request.user = change.user change.undo() @@ -376,10 +399,14 @@ def revert(self, user, commit=True): raise e # Update the Branch's status to "ready" + logger.debug(f"Setting branch status to {BranchStatusChoices.READY}") self.status = BranchStatusChoices.READY self.merged_time = None self.merged_by = None self.save() + + # Record a branch event for the merge + logger.debug(f"Recording branch event: {BranchEventTypeChoices.REVERTED}") BranchEvent.objects.create(branch=self, user=user, type=BranchEventTypeChoices.REVERTED) # Emit branch_reverted signal @@ -494,6 +521,7 @@ def deprovision(self): with connection.cursor() as cursor: # Delete the schema and all its tables + logger.debug(f'Deleting schema {self.schema_name}') cursor.execute( f"DROP SCHEMA IF EXISTS {self.schema_name} CASCADE" ) diff --git a/netbox_branching/models/changes.py b/netbox_branching/models/changes.py index b8c7a94..8c894db 100644 --- a/netbox_branching/models/changes.py +++ b/netbox_branching/models/changes.py @@ -1,3 +1,4 @@ +import logging from functools import cached_property from django.contrib.contenttypes.fields import GenericForeignKey @@ -30,13 +31,14 @@ def apply(self, using=DEFAULT_DB_ALIAS): """ Apply the change using the specified database connection. """ + logger = logging.getLogger('netbox_branching.models.ObjectChange.apply') model = self.changed_object_type.model_class() - print(f'Applying change {self} using {using}') + logger.debug(f'Applying change {self} using {using}') # Creating a new object if self.action == ObjectChangeActionChoices.ACTION_CREATE: instance = deserialize_object(model, self.postchange_data, pk=self.changed_object_id) - print(f'Creating {model._meta.verbose_name} {instance}') + logger.debug(f'Creating {model._meta.verbose_name} {instance}') instance.object.full_clean() instance.save(using=using) @@ -49,10 +51,10 @@ def apply(self, using=DEFAULT_DB_ALIAS): elif self.action == ObjectChangeActionChoices.ACTION_DELETE: try: instance = model.objects.get(pk=self.changed_object_id) - print(f'Deleting {model._meta.verbose_name} {instance}') + logger.debug(f'Deleting {model._meta.verbose_name} {instance}') instance.delete(using=using) except model.DoesNotExist: - print(f'{model._meta.verbose_name} ID {self.changed_object_id} already deleted; skipping') + logger.debug(f'{model._meta.verbose_name} ID {self.changed_object_id} already deleted; skipping') # Rebuild the MPTT tree where applicable if issubclass(model, MPTTModel): @@ -64,16 +66,17 @@ def undo(self, using=DEFAULT_DB_ALIAS): """ Revert a previously applied change using the specified database connection. """ + logger = logging.getLogger('netbox_branching.models.ObjectChange.undo') model = self.changed_object_type.model_class() # Deleting a previously created object if self.action == ObjectChangeActionChoices.ACTION_CREATE: try: instance = model.objects.get(pk=self.changed_object_id) - print(f'Undoing creation of {model._meta.verbose_name} {instance}') + logger.debug(f'Undoing creation of {model._meta.verbose_name} {instance}') instance.delete(using=using) except model.DoesNotExist: - print(f'{model._meta.verbose_name} ID {self.changed_object_id} does not exist; skipping') + logger.debug(f'{model._meta.verbose_name} ID {self.changed_object_id} does not exist; skipping') # Reverting a modification to an object elif self.action == ObjectChangeActionChoices.ACTION_UPDATE: @@ -83,7 +86,7 @@ def undo(self, using=DEFAULT_DB_ALIAS): # Restoring a deleted object elif self.action == ObjectChangeActionChoices.ACTION_DELETE: instance = deserialize_object(model, self.prechange_data, pk=self.changed_object_id) - print(f'Restoring {model._meta.verbose_name} {instance}') + logger.debug(f'Restoring {model._meta.verbose_name} {instance}') instance.object.full_clean() instance.save(using=using) diff --git a/netbox_branching/signal_receivers.py b/netbox_branching/signal_receivers.py index 817493a..da59578 100644 --- a/netbox_branching/signal_receivers.py +++ b/netbox_branching/signal_receivers.py @@ -1,3 +1,4 @@ +import logging from functools import partial from django.db import DEFAULT_DB_ALIAS @@ -31,6 +32,8 @@ def record_change_diff(instance, **kwargs): """ When an ObjectChange is created, create or update the relevant ChangeDiff for the active Branch. """ + logger = logging.getLogger('netbox_branching.signal_receivers.record_change_diff') + branch = active_branch.get() object_type = instance.changed_object_type object_id = instance.changed_object_id @@ -46,7 +49,7 @@ def record_change_diff(instance, **kwargs): if instance.action == ObjectChangeActionChoices.ACTION_CREATE: return - print(f"Updating change diff for global change to {instance.changed_object}") + logger.debug(f"Updating change diff for global change to {instance.changed_object}") ChangeDiff.objects.filter( object_type=object_type, object_id=object_id, @@ -61,7 +64,7 @@ def record_change_diff(instance, **kwargs): # Updating the existing ChangeDiff if diff := ChangeDiff.objects.filter(object_type=object_type, object_id=object_id, branch=branch).first(): - print(f"Updating branch change diff for change to {instance.changed_object}") + logger.debug(f"Updating branch change diff for change to {instance.changed_object}") diff.last_updated = timezone.now() if diff.action != ObjectChangeActionChoices.ACTION_CREATE: diff.action = instance.action @@ -70,7 +73,7 @@ def record_change_diff(instance, **kwargs): # Creating a new ChangeDiff else: - print(f"Creating branch change diff for change to {instance.changed_object}") + logger.debug(f"Creating branch change diff for change to {instance.changed_object}") if instance.action == ObjectChangeActionChoices.ACTION_CREATE: current_data = None else: @@ -93,6 +96,9 @@ def handle_branch_event(event_type, branch, user=None, **kwargs): """ Process any EventRules associated with branch events (e.g. syncing or merging). """ + logger = logging.getLogger('netbox_branching.signal_receivers.handle_branch_event') + logger.debug(f"Checking for {event_type} event rules") + # Find any EventRules for this event type object_type = ObjectType.objects.get_by_natural_key('netbox_branching', 'branch') event_rules = EventRule.objects.filter( @@ -100,6 +106,10 @@ def handle_branch_event(event_type, branch, user=None, **kwargs): enabled=True, object_types=object_type ) + if not event_rules: + logger.debug("No matching event rules found") + return + logger.debug(f"Found {len(event_rules)} event rules") # Serialize the branch & process EventRules username = user.username if user else None