Skip to content

Closes #71: Apply logging consistently for all branch operations #77

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 5, 2024
Merged

Closes #71: Apply logging consistently for all branch operations #77

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 34 additions & 6 deletions netbox_branching/models/branches.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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}")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

would be good to include branch name in all debug log messages

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We include the branch name in the initial INFO message at the start of each operation, which seems like it should be sufficient IMO. I'm wary of making the logs too verbose, but it's something we can re-evaluate over time for sure.

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()
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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()
Expand All @@ -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
Expand Down Expand Up @@ -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"
)
Expand Down
17 changes: 10 additions & 7 deletions netbox_branching/models/changes.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
from functools import cached_property

from django.contrib.contenttypes.fields import GenericForeignKey
Expand Down Expand Up @@ -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)

Expand All @@ -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):
Expand All @@ -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:
Expand All @@ -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)

Expand Down
16 changes: 13 additions & 3 deletions netbox_branching/signal_receivers.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
from functools import partial

from django.db import DEFAULT_DB_ALIAS
Expand Down Expand Up @@ -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
Expand All @@ -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,
Expand All @@ -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
Expand All @@ -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:
Expand All @@ -93,13 +96,20 @@ 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(
event_types__contains=[event_type],
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
Expand Down