diff --git a/config/settings.py b/config/settings.py index adc51d5e9..d0a0c7981 100644 --- a/config/settings.py +++ b/config/settings.py @@ -189,6 +189,9 @@ # In our case, every hour ~200 tasks are executed. Reasonable number is then (200 / concurrency). CELERY_WORKER_MAX_TASKS_PER_CHILD = 60 +LOG_IGNORE_AUTO_TIMESTAMPS = get_env( + "LOG_IGNORE_AUTO_TIMESTAMPS", default="False", is_bool=True +) LOGGING = { "version": 1, "disable_existing_loggers": False, diff --git a/osidb/mixins.py b/osidb/mixins.py index 91dfc2713..8cd8297e9 100644 --- a/osidb/mixins.py +++ b/osidb/mixins.py @@ -16,6 +16,7 @@ from django.db import IntegrityError, models, transaction from django.utils import timezone +from config.settings import LOG_IGNORE_AUTO_TIMESTAMPS from osidb.exceptions import DataInconsistencyException from .core import generate_acls @@ -75,7 +76,7 @@ def save(self, *args, auto_timestamps=True, **kwargs): raise DataInconsistencyException( "Save operation based on an outdated model instance: " f"Updated datetime in the request {self.updated_dt} " - f"differes from the DB {db_self.updated_dt}. " + f"differs from the DB {db_self.updated_dt}. " "You need to refresh." ) @@ -83,6 +84,12 @@ def save(self, *args, auto_timestamps=True, **kwargs): # cut off the microseconds to allow mid-air # collision comparison as API works in seconds self.updated_dt = timezone.now().replace(microsecond=0) + elif LOG_IGNORE_AUTO_TIMESTAMPS: + db_self = type(self).objects.filter(pk=self.pk).first() + if db_self is not None and db_self.updated_dt != self.updated_dt: + logger.warning( + f"saved outdated model instance {self.__class__.__name__}, id: {self.pk}, db_updated_dt: {db_self.updated_dt}, self_updated_dt: {self.updated_dt}" + ) super().save(*args, **kwargs) diff --git a/osidb/signals.py b/osidb/signals.py index 59985fda5..6f8fb1c27 100644 --- a/osidb/signals.py +++ b/osidb/signals.py @@ -32,6 +32,17 @@ logger = logging.getLogger(__name__) +def log_signal_update(instance, sender, handler_name, *, flaw=None): + logger.info( + "signal_parent_save handler=%s sender=%s instance_model=%s instance_pk=%s flaw_pk=%s", + handler_name, + getattr(sender, "__name__", str(sender)), + type(instance).__name__, + getattr(instance, "pk", None), + flaw.pk if flaw is not None else None, + ) + + def get_bz_user_id(email: str) -> str: api_key = get_env("BZIMPORT_BZ_API_KEY") bz_url = get_env("BZIMPORT_BZ_URL", "https://bugzilla.redhat.com") @@ -126,6 +137,9 @@ def update_flaw_fields(sender, instance, **kwargs): @receiver(post_save, sender=FlawCollaborator) @receiver(post_save, sender=FlawCVSS) def flaw_dependant_update_local_updated_dt(sender, instance, **kwargs): + log_signal_update( + instance, sender, "flaw_dependant_update_local_updated_dt", flaw=instance.flaw + ) instance.flaw.save(auto_timestamps=False, raise_validation_error=False) @@ -140,6 +154,9 @@ def update_local_updated_dt_tracker(sender, instance, **kwargs): for affect in instance.affects.all(): flaws.add(affect.flaw) for flaw in list(flaws): + log_signal_update( + instance, sender, "update_local_updated_dt_tracker", flaw=flaw + ) flaw.save( auto_timestamps=False, no_alerts=True, # recreating alerts from nested entities can cause deadlocks @@ -149,6 +166,12 @@ def update_local_updated_dt_tracker(sender, instance, **kwargs): @receiver(post_save, sender=AffectCVSS) def updated_local_updated_dt_affectcvss(sender, instance, **kwargs): + log_signal_update( + instance, + sender, + "updated_local_updated_dt_affectcvss", + flaw=instance.affect.flaw, + ) instance.affect.flaw.save(auto_timestamps=False, raise_validation_error=False)