diff --git a/CHANGELOG.md b/CHANGELOG.md index c11b1a21..51b4dd4b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,12 @@ List of the most important changes for each release. +## 0.8.11 +- Adds additional `deserialization_exception` field to `Store` model to track the fully qualified exception path + +## 0.8.10 +- Fixes silent failure during deserialization of records that fail unique constraints + ## 0.8.9 - Removes debugging print statements - Adds flake8 linting diff --git a/morango/errors.py b/morango/errors.py index 8a2d2b52..31d885dd 100644 --- a/morango/errors.py +++ b/morango/errors.py @@ -1,5 +1,10 @@ +from morango.utils import exception_path + + class MorangoError(Exception): - pass + @classmethod + def path(cls): + return exception_path(cls) class ModelRegistryNotReady(MorangoError): @@ -80,3 +85,11 @@ class MorangoSkipOperation(MorangoError): class MorangoDatabaseError(MorangoError): pass + + +class MorangoDirtyParent(MorangoError): + pass + + +class MorangoMissingParent(MorangoError): + pass diff --git a/morango/migrations/0003_store_deserialization_errors.py b/morango/migrations/0003_store_deserialization_errors.py new file mode 100644 index 00000000..baf09ab3 --- /dev/null +++ b/morango/migrations/0003_store_deserialization_errors.py @@ -0,0 +1,21 @@ +# Generated by Django 3.2.25 on 2026-04-14 15:54 +from django.db import migrations, models + + +class Migration(migrations.Migration): + dependencies = [ + ("morango", "0002_store_idx_morango_deserialize"), + ] + + operations = [ + migrations.AddField( + model_name="store", + name="deserialization_exception", + field=models.CharField(blank=True, max_length=255, null=True), + ), + migrations.AlterField( + model_name="store", + name="deserialization_error", + field=models.TextField(blank=True, null=True), + ), + ] diff --git a/morango/models/core.py b/morango/models/core.py index 06abf3ff..8c720084 100644 --- a/morango/models/core.py +++ b/morango/models/core.py @@ -24,7 +24,7 @@ from morango.models.manager import SyncableModelManager from morango.models.utils import get_0_4_system_parameters, get_0_5_mac_address, get_0_5_system_id from morango.registry import syncable_models -from morango.utils import SETTINGS, _assert +from morango.utils import SETTINGS, _assert, exception_path logger = logging.getLogger(__name__) @@ -429,7 +429,8 @@ class Store(AbstractStore): id = UUIDField(primary_key=True) # used to know which store records need to be deserialized into the app layer models dirty_bit = models.BooleanField(default=False) - deserialization_error = models.TextField(blank=True) + deserialization_error = models.TextField(blank=True, null=True) + deserialization_exception = models.CharField(max_length=255, blank=True, null=True) last_transfer_session_id = UUIDField(blank=True, null=True, default=None, db_index=True) @@ -445,6 +446,14 @@ class Meta: ), ] + def set_deserialization_error(self, exc): + self.deserialization_error = str(exc) + self.deserialization_exception = exception_path(exc) + + def unset_deserialization_error(self): + self.deserialization_error = None + self.deserialization_exception = None + def _deserialize_store_model(self, fk_cache, defer_fks=False, sync_filter=None): # noqa: C901 """ When deserializing a store model, we look at the deleted flags to know if we should delete the app model. diff --git a/morango/sync/backends/postgres.py b/morango/sync/backends/postgres.py index e466ded6..c560b3e5 100644 --- a/morango/sync/backends/postgres.py +++ b/morango/sync/backends/postgres.py @@ -203,22 +203,53 @@ def _dequeuing_merge_conflict_rmcb(self, cursor, transfersession_id): def _dequeuing_merge_conflict_buffer(self, cursor, current_id, transfersession_id): # transfer buffer serialized into conflicting store - merge_conflict_store = """UPDATE {store} as store SET (serialized, deleted, last_saved_instance, last_saved_counter, hard_deleted, model_name, - profile, partition, source_id, conflicting_serialized_data, dirty_bit, _self_ref_fk, deserialization_error, last_transfer_session_id) - = (CASE buffer.hard_deleted WHEN TRUE THEN '' ELSE store.serialized END, store.deleted OR buffer.deleted, '{current_instance_id}', - {current_instance_counter}, store.hard_deleted, store.model_name, store.profile, store.partition, store.source_id, - CASE buffer.hard_deleted WHEN TRUE THEN '' ELSE buffer.serialized || '\n' || store.conflicting_serialized_data END, TRUE, store._self_ref_fk, - '', '{transfer_session_id}') - /*Scope to a single record.*/ - FROM {buffer} AS buffer - WHERE store.id = buffer.model_uuid - AND buffer.transfer_session_id = '{transfer_session_id}' - /*Exclude fast-forwards*/ - AND NOT EXISTS (SELECT 1 FROM {rmcb} AS rmcb2 WHERE store.id = rmcb2.model_uuid - AND store.last_saved_instance = rmcb2.instance_id - AND store.last_saved_counter <= rmcb2.counter - AND rmcb2.transfer_session_id = '{transfer_session_id}') - """.format( + merge_conflict_store = """ + UPDATE {store} as store SET ( + serialized, + deleted, + last_saved_instance, + last_saved_counter, + hard_deleted, + model_name, + profile, + partition, + source_id, + conflicting_serialized_data, + dirty_bit, + _self_ref_fk, + deserialization_error, + deserialization_exception, + last_transfer_session_id + ) = ( + CASE buffer.hard_deleted WHEN TRUE THEN '' ELSE store.serialized END, + store.deleted OR buffer.deleted, + '{current_instance_id}', + {current_instance_counter}, + store.hard_deleted, + store.model_name, + store.profile, + store.partition, + store.source_id, + CASE buffer.hard_deleted WHEN TRUE THEN '' ELSE buffer.serialized || '\n' || store.conflicting_serialized_data END, + TRUE, + store._self_ref_fk, + NULL, + NULL, + '{transfer_session_id}' + ) + /*Scope to a single record.*/ + FROM {buffer} AS buffer + WHERE store.id = buffer.model_uuid + AND buffer.transfer_session_id = '{transfer_session_id}' + /*Exclude fast-forwards*/ + AND NOT EXISTS ( + SELECT 1 FROM {rmcb} AS rmcb2 + WHERE store.id = rmcb2.model_uuid + AND store.last_saved_instance = rmcb2.instance_id + AND store.last_saved_counter <= rmcb2.counter + AND rmcb2.transfer_session_id = '{transfer_session_id}' + ) + """.format( buffer=Buffer._meta.db_table, rmcb=RecordMaxCounterBuffer._meta.db_table, store=Store._meta.db_table, @@ -277,27 +308,96 @@ def _dequeuing_insert_remaining_buffer(self, cursor, transfersession_id): insert_remaining_buffer = """ WITH new_values as ( - SELECT buffer.model_uuid, buffer.serialized, buffer.deleted, buffer.last_saved_instance, buffer.last_saved_counter, buffer.hard_deleted, - buffer.model_name, buffer.profile, buffer.partition, buffer.source_id, buffer.conflicting_serialized_data, buffer._self_ref_fk + SELECT + buffer.model_uuid, + buffer.serialized, + buffer.deleted, + buffer.last_saved_instance, + buffer.last_saved_counter, + buffer.hard_deleted, + buffer.model_name, + buffer.profile, + buffer.partition, + buffer.source_id, + buffer.conflicting_serialized_data, + buffer._self_ref_fk FROM {buffer} as buffer WHERE buffer.transfer_session_id = '{transfer_session_id}' ), updated as ( - UPDATE {store} store SET (serialized, deleted, last_saved_instance, last_saved_counter, hard_deleted, model_name, profile, - partition, source_id, conflicting_serialized_data, dirty_bit, _self_ref_fk, deserialization_error, last_transfer_session_id) - = (nv.serialized, nv.deleted, nv.last_saved_instance, nv.last_saved_counter, nv.hard_deleted, - nv.model_name, nv.profile, nv.partition, nv.source_id, nv.conflicting_serialized_data, TRUE, - nv._self_ref_fk, '', '{transfer_session_id}') + UPDATE {store} store SET ( + serialized, + deleted, + last_saved_instance, + last_saved_counter, + hard_deleted, + model_name, + profile, + partition, + source_id, + conflicting_serialized_data, + dirty_bit, + _self_ref_fk, + deserialization_error, + deserialization_exception, + last_transfer_session_id + ) = ( + nv.serialized, + nv.deleted, + nv.last_saved_instance, + nv.last_saved_counter, + nv.hard_deleted, + nv.model_name, + nv.profile, + nv.partition, + nv.source_id, + nv.conflicting_serialized_data, + TRUE, + nv._self_ref_fk, + NULL, + NULL, + '{transfer_session_id}' + ) FROM new_values nv WHERE nv.model_uuid = store.id returning store.* ) - INSERT INTO {store}(id, serialized, deleted, last_saved_instance, last_saved_counter, hard_deleted, model_name, profile, - partition, source_id, conflicting_serialized_data, dirty_bit, _self_ref_fk, deserialization_error, last_transfer_session_id) - SELECT ut.model_uuid, ut.serialized, ut.deleted, ut.last_saved_instance, ut.last_saved_counter, ut.hard_deleted, - ut.model_name, ut.profile, ut.partition, ut.source_id, ut.conflicting_serialized_data, TRUE, - ut._self_ref_fk, '', '{transfer_session_id}' + INSERT INTO {store}( + id, + serialized, + deleted, + last_saved_instance, + last_saved_counter, + hard_deleted, + model_name, + profile, + partition, + source_id, + conflicting_serialized_data, + dirty_bit, + _self_ref_fk, + deserialization_error, + deserialization_exception, + last_transfer_session_id + ) + SELECT + ut.model_uuid, + ut.serialized, + ut.deleted, + ut.last_saved_instance, + ut.last_saved_counter, + ut.hard_deleted, + ut.model_name, + ut.profile, + ut.partition, + ut.source_id, + ut.conflicting_serialized_data, + TRUE, + ut._self_ref_fk, + NULL, + NULL, + '{transfer_session_id}' FROM new_values ut WHERE ut.model_uuid not in (SELECT id FROM updated) """.format( diff --git a/morango/sync/backends/sqlite.py b/morango/sync/backends/sqlite.py index c0c60fac..38b31446 100644 --- a/morango/sync/backends/sqlite.py +++ b/morango/sync/backends/sqlite.py @@ -136,22 +136,61 @@ def _dequeuing_merge_conflict_rmcb(self, cursor, transfersession_id): def _dequeuing_merge_conflict_buffer(self, cursor, current_id, transfersession_id): # transfer buffer serialized into conflicting store - merge_conflict_store = """REPLACE INTO {store} (id, serialized, deleted, last_saved_instance, last_saved_counter, hard_deleted, model_name, profile, partition, - source_id, conflicting_serialized_data, dirty_bit, _self_ref_fk, deserialization_error, last_transfer_session_id) - SELECT store.id, CASE buffer.hard_deleted WHEN 1 THEN '' ELSE store.serialized END, store.deleted OR buffer.deleted, '{current_instance_id}', - {current_instance_counter}, store.hard_deleted OR buffer.hard_deleted, store.model_name, store.profile, store.partition, store.source_id, - CASE buffer.hard_deleted WHEN 1 THEN '' ELSE buffer.serialized || '\n' || store.conflicting_serialized_data END, 1, store._self_ref_fk, - '', '{transfer_session_id}' - FROM {buffer} AS buffer, {store} AS store - /*Scope to a single record.*/ - WHERE store.id = buffer.model_uuid - AND buffer.transfer_session_id = '{transfer_session_id}' - /*Exclude fast-forwards*/ - AND NOT EXISTS (SELECT 1 FROM {rmcb} AS rmcb2 WHERE store.id = rmcb2.model_uuid - AND store.last_saved_instance = rmcb2.instance_id - AND store.last_saved_counter <= rmcb2.counter - AND rmcb2.transfer_session_id = '{transfer_session_id}') - """.format( + merge_conflict_store = """ + REPLACE INTO {store} ( + id, + serialized, + deleted, + last_saved_instance, + last_saved_counter, + hard_deleted, + model_name, + profile, + partition, + source_id, + conflicting_serialized_data, + dirty_bit, + _self_ref_fk, + deserialization_error, + deserialization_exception, + last_transfer_session_id + ) + SELECT + store.id, + CASE buffer.hard_deleted WHEN 1 THEN '' ELSE store.serialized END, + store.deleted OR buffer.deleted, + '{current_instance_id}', + {current_instance_counter}, + store.hard_deleted OR buffer.hard_deleted, + store.model_name, + store.profile, + store.partition, + store.source_id, + ( + CASE buffer.hard_deleted + WHEN 1 + THEN '' + ELSE buffer.serialized || '\n' || store.conflicting_serialized_data + END + ), + 1, + store._self_ref_fk, + NULL, + NULL, + '{transfer_session_id}' + FROM {buffer} AS buffer, {store} AS store + /*Scope to a single record.*/ + WHERE store.id = buffer.model_uuid + AND buffer.transfer_session_id = '{transfer_session_id}' + /*Exclude fast-forwards*/ + AND NOT EXISTS ( + SELECT 1 FROM {rmcb} AS rmcb2 + WHERE store.id = rmcb2.model_uuid + AND store.last_saved_instance = rmcb2.instance_id + AND store.last_saved_counter <= rmcb2.counter + AND rmcb2.transfer_session_id = '{transfer_session_id}' + ) + """.format( buffer=Buffer._meta.db_table, rmcb=RecordMaxCounterBuffer._meta.db_table, store=Store._meta.db_table, @@ -190,14 +229,45 @@ def _dequeuing_update_rmcs_last_saved_by( def _dequeuing_insert_remaining_buffer(self, cursor, transfersession_id): # insert remaining records into store - insert_remaining_buffer = """REPLACE INTO {store} (id, serialized, deleted, last_saved_instance, last_saved_counter, hard_deleted, model_name, profile, partition, - source_id, conflicting_serialized_data, dirty_bit, _self_ref_fk, deserialization_error, last_transfer_session_id) - SELECT buffer.model_uuid, buffer.serialized, buffer.deleted, buffer.last_saved_instance, buffer.last_saved_counter, buffer.hard_deleted, - buffer.model_name, buffer.profile, buffer.partition, buffer.source_id, buffer.conflicting_serialized_data, 1, - buffer._self_ref_fk, '', '{transfer_session_id}' - FROM {buffer} AS buffer - WHERE buffer.transfer_session_id = '{transfer_session_id}' - """.format( + insert_remaining_buffer = """ + REPLACE INTO {store} ( + id, + serialized, + deleted, + last_saved_instance, + last_saved_counter, + hard_deleted, + model_name, + profile, + partition, + source_id, + conflicting_serialized_data, + dirty_bit, + _self_ref_fk, + deserialization_error, + deserialization_exception, + last_transfer_session_id + ) + SELECT + buffer.model_uuid, + buffer.serialized, + buffer.deleted, + buffer.last_saved_instance, + buffer.last_saved_counter, + buffer.hard_deleted, + buffer.model_name, + buffer.profile, + buffer.partition, + buffer.source_id, + buffer.conflicting_serialized_data, + 1, + buffer._self_ref_fk, + NULL, + NULL, + '{transfer_session_id}' + FROM {buffer} AS buffer + WHERE buffer.transfer_session_id = '{transfer_session_id}' + """.format( buffer=Buffer._meta.db_table, store=Store._meta.db_table, transfer_session_id=transfersession_id, diff --git a/morango/sync/operations.py b/morango/sync/operations.py index 1924fc70..ca41cf1a 100644 --- a/morango/sync/operations.py +++ b/morango/sync/operations.py @@ -7,9 +7,15 @@ from django.core import exceptions from django.db import connection +from django.db import transaction from django.db.models import CharField +from django.db.models import F from django.db.models import Q from django.db.models import signals +from django.db.models import Value +from django.db.models.fields import BooleanField +from django.db.models.functions import NullIf +from django.db.utils import IntegrityError from django.db.utils import OperationalError from django.utils import timezone from rest_framework.exceptions import ValidationError @@ -19,8 +25,10 @@ from morango.constants import transfer_statuses from morango.constants.capabilities import ASYNC_OPERATIONS from morango.constants.capabilities import FSIC_V2_FORMAT +from morango.errors import MorangoDirtyParent from morango.errors import MorangoInvalidFSICPartition from morango.errors import MorangoLimitExceeded +from morango.errors import MorangoMissingParent from morango.errors import MorangoResumeSyncError from morango.errors import MorangoSkipOperation from morango.models.certificates import Filter @@ -49,6 +57,7 @@ from morango.sync.utils import validate_and_create_buffer_data from morango.utils import _assert from morango.utils import self_referential_fk +from morango.utils import exception_path from morango.utils import SETTINGS logger = logging.getLogger(__name__) @@ -106,10 +115,10 @@ def _validate_missing_store_foreign_keys(from_model_name, to_model_name, temp_ta pk_field=Store._meta.pk.column, ) - store_deserialization_error = next( - f for f in Store._meta.fields if f.name == "deserialization_error" - ) - store_update_fields = [Store._meta.pk, store_deserialization_error] + store_deserialization_error_fields = [ + f for f in Store._meta.fields if f.name in ("deserialization_error", "deserialization_exception") + ] + store_update_fields = [Store._meta.pk, *store_deserialization_error_fields] from_pk_field = temp_table.get_field("from_pk") to_pk_field = temp_table.get_field("to_pk") @@ -117,22 +126,21 @@ def _validate_missing_store_foreign_keys(from_model_name, to_model_name, temp_ta with connection.cursor() as c: c.execute(select_sql) for from_field, from_pk, to_pk in c.fetchall(): - err = dict( - { - from_field: "{to_model_name} instance with id '{to_pk}' does not exist".format( - to_model_name=to_model_name, - to_pk=to_pk_field.to_python(to_pk), - ) - } + err = IntegrityError( + "{from_model_name}.{from_field} references non-existent {to_model_name} instance with id '{to_pk}'".format( + from_model_name=from_model_name, + from_field=from_field, + to_model_name=to_model_name, + to_pk=to_pk_field.to_python(to_pk), + ) ) logger.warning( - "Error deserializing instance of {from_model} with id {from_pk}: {err}".format( - from_model=from_model_name, + "Error deserializing instance with id {from_pk}: {err}".format( from_pk=from_pk, err=str(err), ) ) - update_values.extend([from_pk, str(err)]) + update_values.extend([from_pk, str(err), exception_path(err)]) invalid_pks.append(from_pk_field.to_python(from_pk)) if update_values: # update Store with errors @@ -228,6 +236,46 @@ def _validate_store_foreign_keys(from_model_name, fk_references): return exclude_pks, deleted_pks +def _save_deserialized_record(store_model, app_model, model_name, excluded_list=None): + """ + Attempt to save one deserialized app model into the app table. + + On success: clears dirty_bit and deserialization_error on the Store record. + On failure: records the error on the Store record, keeps dirty_bit True, + and logs a warning. + + :returns: True if save succeeded, False otherwise + """ + + try: + with transaction.atomic(): + with mute_signals(signals.pre_save, signals.post_save): + app_model.save(update_dirty_bit_to=False) + store_model.dirty_bit = False + store_model.unset_deserialization_error() + store_model.save( + update_fields=["dirty_bit", "deserialization_error", "deserialization_exception"] + ) + return True + except ( + exceptions.ValidationError, + exceptions.ObjectDoesNotExist, + ValueError, + IntegrityError, + ) as e: + if excluded_list is not None: + excluded_list.append(store_model.id) + store_model.set_deserialization_error(e) + store_model.save(update_fields=["deserialization_error", "deserialization_exception"]) + logger.warning( + "Failed to deserialize Store record %s for %s: %s", + store_model.id, + model_name, + e, + ) + return False + + def _deserialize_from_store(profile, skip_erroring=False, filter=None): """ Takes data from the store and integrates into the application. @@ -235,7 +283,9 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): ALGORITHM: On a per syncable model basis, we iterate through each class model and we go through 2 possible cases: 1. For class models that have a self referential foreign key, we iterate down the dependency tree deserializing model by model. - 2. On a per app model basis, we append the field values to a single list, and do a single bulk insert/replace query. + 2. For other models, we deserialize and validate each record, then save individually so that DB-level errors + (e.g. unique constraint violations) are caught and recorded per-record rather than silently lost or crashing + the entire deserialization. If a model fails to deserialize/validate, we exclude it from being marked as clean in the store. """ @@ -266,7 +316,20 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): # if requested, skip any records that previously errored, to be faster if skip_erroring: - store_models = store_models.filter(deserialization_error="") + # previously, deserialization_error was not nullable, and set to empty string if + # there wasn't an error, so this nullifies empty strings to ensure the filter + # applies either way + store_models = ( + store_models + .annotate( + n_deserialization_error=NullIf( + F("deserialization_error"), + Value(""), + output_field=BooleanField() + ) + ) + .filter(n_deserialization_error__isnull=True) + ) # handle cases where a class has a single FK reference to itself if self_referential_fk(model): @@ -284,24 +347,25 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): app_model, _ = store_model._deserialize_store_model( fk_cache, sync_filter=filter ) - if app_model: - with mute_signals(signals.pre_save, signals.post_save): - app_model.save(update_dirty_bit_to=False) - # we update a store model after we have deserialized it to be able to mark it as a clean parent - store_model.dirty_bit = False - store_model.deserialization_error = "" - store_model.save( - update_fields=["dirty_bit", "deserialization_error"] - ) except ( exceptions.ValidationError, exceptions.ObjectDoesNotExist, ValueError, ) as e: excluded_list.append(store_model.id) - # if the app model did not validate, we leave the store dirty bit set, but mark the error - store_model.deserialization_error = str(e) - store_model.save(update_fields=["deserialization_error"]) + store_model.set_deserialization_error(e) + store_model.save(update_fields=["deserialization_error", "deserialization_exception"]) + continue + if app_model: + _save_deserialized_record( + store_model, app_model, model.__name__, excluded_list + ) + else: + store_model.dirty_bit = False + store_model.unset_deserialization_error() + store_model.save( + update_fields=["dirty_bit", "deserialization_error", "deserialization_exception"] + ) # update lists with new clean parents and dirty children clean_parents = store_models.filter(dirty_bit=False).char_ids_list() @@ -315,20 +379,21 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): store_models.filter( dirty_bit=True, _self_ref_fk__in=dirty_parents ).exclude(id__in=excluded_list).update( - deserialization_error="Parent is dirty; could not deserialize." + deserialization_error="Parent is dirty; could not deserialize.", + deserialization_exception=MorangoDirtyParent.path(), ) # A(ii). The ones that don't even have Store entries for parent at all all_parents = store_models.char_ids_list() store_models.filter(dirty_bit=True).exclude( _self_ref_fk__in=all_parents ).exclude(id__in=excluded_list).update( - deserialization_error="Parent does not exist in Store; could not deserialize." + deserialization_error="Parent does not exist in Store; could not deserialize.", + deserialization_exception=MorangoMissingParent.path(), ) else: - # collect all initially valid app models + # collect all initially valid app models and validate their FKs app_models = [] - fields = model._meta.fields for store_model in store_models.filter(dirty_bit=True): try: ( @@ -340,7 +405,7 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): sync_filter=filter, ) if app_model: - app_models.append(app_model) + app_models.append((store_model, app_model)) for fk_model, fk_refs in model_deferred_fks.items(): # validate that the FK references aren't to anything already in the # excluded list, which should only contain models which failed to @@ -360,8 +425,8 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): ) as e: # if the app model did not validate, we leave the store dirty bit set excluded_list.append(store_model.id) - store_model.deserialization_error = str(e) - store_model.save(update_fields=["deserialization_error"]) + store_model.set_deserialization_error(e) + store_model.save(update_fields=["deserialization_error", "deserialization_exception"]) # validate app model FKs model_excluded_pks, model_deleted_pks = _validate_store_foreign_keys( @@ -370,40 +435,17 @@ def _deserialize_from_store(profile, skip_erroring=False, filter=None): excluded_list.extend(model_excluded_pks) deleted_list.extend(model_deleted_pks) - # array for holding db values from the fields of each model for this class - db_values = [] - for app_model in app_models: + # save each app model individually so we can catch per-record + # DB-level errors (e.g. unique constraint violations) + for store_model, app_model in app_models: if ( - app_model.pk not in excluded_list - and app_model.pk not in deleted_list + app_model.pk in excluded_list + or app_model.pk in deleted_list ): - # handle any errors that might come from `get_db_prep_value` - try: - new_db_values = [] - for f in fields: - value = getattr(app_model, f.attname) - db_value = f.get_db_prep_value(value, connection) - new_db_values.append(db_value) - db_values += new_db_values - except ValueError as e: - excluded_list.append(app_model.pk) - store_model = store_models.get(pk=app_model.pk) - store_model.deserialization_error = str(e) - store_model.save(update_fields=["deserialization_error"]) - - if db_values: - with connection.cursor() as cursor: - DBBackend._bulk_full_record_upsert( - cursor, - model._meta.db_table, - fields, - db_values, - ) - - # clear dirty bit for all store records for this model/profile except for rows that did not validate - store_models.exclude(id__in=excluded_list).filter( - dirty_bit=True - ).update(dirty_bit=False) + continue + _save_deserialized_record( + store_model, app_model, model.__name__ + ) def _queue_into_buffer_v1(transfersession): diff --git a/morango/utils.py b/morango/utils.py index 0143f083..2db616e0 100644 --- a/morango/utils.py +++ b/morango/utils.py @@ -140,3 +140,17 @@ def self_referential_fk(klass_model): if issubclass(klass_model, f.related_model): return f.attname return None + + +def exception_path(exc): + """ + Produces a string of the fully qualified class name of the exception + + :param exc: An exception instance + :type exc: Exception|Type[Exception] + :return: A string of the fully qualified class name of the exception + """ + exc_cls = exc + if isinstance(exc, Exception): + exc_cls = exc.__class__ + return f"{exc_cls.__module__}.{exc_cls.__name__}" diff --git a/tests/testapp/tests/helpers.py b/tests/testapp/tests/helpers.py index d5a3f90e..94e9187b 100644 --- a/tests/testapp/tests/helpers.py +++ b/tests/testapp/tests/helpers.py @@ -8,9 +8,6 @@ import factory import mock from django.core.serializers.json import DjangoJSONEncoder -from django.db import connection -from django.db.migrations.executor import MigrationExecutor -from django.db.migrations.recorder import MigrationRecorder from django.test.testcases import LiveServerTestCase from django.utils import timezone from facility_profile.models import Facility, InteractionLog, MyUser, SummaryLog @@ -412,64 +409,3 @@ def stage_status(self): def update_state(self, stage=None, stage_status=None): self._stage = stage or self._stage self._stage_status = stage_status or self._stage_status - - -class TestMigrationsMixin(object): - # Modified from https://www.caktusgroup.com/blog/2016/02/02/writing-unit-tests-django-migrations/ - # Note that this has been updated to handle running migration tests for previously squashed migrations. - # It is possible this will no longer work for testing migrations that are part of or - # subsequent to a squashed migration. - - migrate_from = None - migrate_to = None - app = None - - @classmethod - def setUpClass(cls): - super(TestMigrationsMixin, cls).setUpClass() - - # get the latest migration before starting - latest_migration = MigrationRecorder.Migration.objects.filter(app=cls.app).last() - cls.latest_migration = (cls.app, latest_migration.name) - - def setUp(self): - assert self.migrate_from and self.migrate_to, ( - "TestCase '{}' must define migrate_from and migrate_to properties".format( - type(self).__name__ - ) - ) - - migrate_from = [(self.app, self.migrate_from)] - migrate_to = [(self.app, self.migrate_to)] - executor = MigrationExecutor(connection) - executor.migrate([(self.app, None)]) - executor.loader.replace_migrations = False - executor.loader.build_graph() # reload. - - old_apps = executor.loader.project_state(migrate_from).apps - - # Reverse to the original migration - executor.migrate(migrate_from) - - self.setUpBeforeMigration(old_apps) - - # Run the migration to test - executor = MigrationExecutor(connection) - executor.loader.build_graph() # reload. - executor.migrate(migrate_to) - - self.apps = executor.loader.project_state(migrate_to).apps - - def setUpBeforeMigration(self, apps): - pass - - @classmethod - def tearDownClass(cls): - # revert migration back to latest migration - executor = MigrationExecutor(connection) - executor.migrate([(cls.app, None)]) - executor.loader.replace_migrations = True - executor.loader.build_graph() - executor.migrate([cls.latest_migration]) - - super(TestMigrationsMixin, cls).tearDownClass() diff --git a/tests/testapp/tests/models/test_core.py b/tests/testapp/tests/models/test_core.py index b025ad65..6cd58a6a 100644 --- a/tests/testapp/tests/models/test_core.py +++ b/tests/testapp/tests/models/test_core.py @@ -370,3 +370,108 @@ def test_deferred_clean_fields(self, mock_clean_fields): sync_filter = Filter("test") f.deferred_clean_fields(exclude=["test1"], sync_filter=sync_filter) mock_clean_fields.assert_called_once_with(exclude=["test1"], sync_filter=sync_filter) + + +class StoreDeserializationErrorTestCase(TestCase): + """Tests for Store.set_deserialization_error() and Store.unset_deserialization_error()""" + + def test_set_deserialization_error_with_validation_error(self): + """Test that set_deserialization_error correctly captures ValidationError.""" + from django.core.exceptions import ValidationError + + store = StoreFactory( + id=uuid.uuid4().hex, + partition="test", + serialized="{}", + last_saved_instance="a" * 32, + last_saved_counter=1, + ) + exc = ValidationError("Invalid data") + store.set_deserialization_error(exc) + + # ValidationError str() returns a list representation like "['Invalid data']" + self.assertIn("Invalid data", store.deserialization_error) + self.assertEqual( + store.deserialization_exception, + "django.core.exceptions.ValidationError", + ) + + def test_set_deserialization_error_with_integrity_error(self): + """Test that set_deserialization_error correctly captures IntegrityError.""" + from django.db.utils import IntegrityError + + store = StoreFactory( + id=uuid.uuid4().hex, + partition="test", + serialized="{}", + last_saved_instance="a" * 32, + last_saved_counter=1, + ) + exc = IntegrityError("UNIQUE constraint failed") + store.set_deserialization_error(exc) + + self.assertEqual(store.deserialization_error, "UNIQUE constraint failed") + self.assertEqual( + store.deserialization_exception, + "django.db.utils.IntegrityError", + ) + + def test_set_deserialization_error_with_value_error(self): + """Test that set_deserialization_error correctly captures ValueError.""" + store = StoreFactory( + id=uuid.uuid4().hex, + partition="test", + serialized="{}", + last_saved_instance="a" * 32, + last_saved_counter=1, + ) + exc = ValueError("Invalid value") + store.set_deserialization_error(exc) + + self.assertEqual(store.deserialization_error, "Invalid value") + self.assertEqual( + store.deserialization_exception, + "builtins.ValueError", + ) + + def test_unset_deserialization_error(self): + """Test that unset_deserialization_error clears both fields.""" + store = StoreFactory( + id=uuid.uuid4().hex, + partition="test", + serialized="{}", + last_saved_instance="a" * 32, + last_saved_counter=1, + deserialization_error="some error", + deserialization_exception="module.Error", + ) + + store.unset_deserialization_error() + + self.assertIsNone(store.deserialization_error) + self.assertIsNone(store.deserialization_exception) + + def test_set_and_unset_deserialization_error(self): + """Test that set_deserialization_error followed by unset_deserialization_error works correctly.""" + from django.core.exceptions import ValidationError + + store = StoreFactory( + id=uuid.uuid4().hex, + partition="test", + serialized="{}", + last_saved_instance="a" * 32, + last_saved_counter=1, + ) + + exc = ValidationError("Test error") + store.set_deserialization_error(exc) + # ValidationError str() returns a list representation like "['Test error']" + self.assertIn("Test error", store.deserialization_error) + self.assertEqual( + store.deserialization_exception, + "django.core.exceptions.ValidationError", + ) + + store.unset_deserialization_error() + self.assertIsNone(store.deserialization_error) + self.assertIsNone(store.deserialization_exception) diff --git a/tests/testapp/tests/sync/test_controller.py b/tests/testapp/tests/sync/test_controller.py index 2425df64..d0846e85 100644 --- a/tests/testapp/tests/sync/test_controller.py +++ b/tests/testapp/tests/sync/test_controller.py @@ -519,6 +519,152 @@ def test_filtered_deserialization(self): self.assertFalse(MyUser.objects.filter(username="changed2").exists()) +class UniqueConstraintDeserializationTestCase(TestCase): + """ + Regression tests for silent deserialization failure when two Store records + have different Morango IDs but violate a unique constraint on the app model table. + + On SQLite, ``REPLACE INTO`` silently deletes the conflicting row and inserts the + new one, so no IntegrityError is raised. On PostgreSQL, the ``INSERT`` without an + ``ON CONFLICT`` clause for non-PK constraints would raise IntegrityError. + + In both cases, the expected behavior is: + - The conflicting Store record should have ``deserialization_error`` populated + - Its ``dirty_bit`` should remain True + - A warning should be logged + """ + + def setUp(self): + InstanceIDModel.get_or_create_current_instance() + self.mc = MorangoProfileController("facilitydata") + + def _create_conflicting_user_store_records(self): + """Create two Store records for MyUser with different IDs but the same unique username.""" + self.user1_id = uuid.uuid4().hex + self.user2_id = uuid.uuid4().hex + + user1 = MyUser(id=self.user1_id, username="duplicate", password="password") + user2 = MyUser(id=self.user2_id, username="duplicate", password="password") + + self.store1 = StoreModelFacilityFactory( + id=self.user1_id, + serialized=json.dumps(user1.serialize()), + model_name="user", + ) + self.store2 = StoreModelFacilityFactory( + id=self.user2_id, + serialized=json.dumps(user2.serialize()), + model_name="user", + ) + + def test_unique_violation_sets_deserialization_error(self): + """At least one conflicting record should have deserialization_error set.""" + self._create_conflicting_user_store_records() + + self.mc.deserialize_from_store() + + # At most one app model should exist due to the unique constraint + self.assertLessEqual(MyUser.objects.filter(username="duplicate").count(), 1) + + # Both Store records should still exist + self.assertEqual(Store.objects.filter(id__in=[self.user1_id, self.user2_id]).count(), 2) + + # At least one Store record should have deserialization_error set + errored_stores = Store.objects.filter( + id__in=[self.user1_id, self.user2_id], + deserialization_error__isnull=False, + ) + self.assertGreater( + errored_stores.count(), + 0, + "Expected at least one Store record to have deserialization_error " + "set for unique constraint violation, but none did.", + ) + + def test_unique_violation_leaves_dirty_bit(self): + """The conflicting record's dirty_bit should remain True.""" + self._create_conflicting_user_store_records() + + self.mc.deserialize_from_store() + + # At least one Store record should still have dirty_bit=True + dirty_stores = Store.objects.filter( + id__in=[self.user1_id, self.user2_id], + dirty_bit=True, + ) + self.assertGreater( + dirty_stores.count(), + 0, + "Expected at least one Store record to still have dirty_bit=True " + "for a unique constraint violation, but all were cleared.", + ) + + def test_unique_violation_logs_warning(self): + """A warning should be logged when deserialization fails due to a unique constraint.""" + self._create_conflicting_user_store_records() + + with self.assertLogs("morango.sync.operations", level="WARNING") as cm: + self.mc.deserialize_from_store() + + unique_warnings = [ + msg for msg in cm.output if "unique" in msg.lower() or "integrity" in msg.lower() + ] + self.assertGreater( + len(unique_warnings), + 0, + "Expected a warning log about unique constraint violation during " + "deserialization, but none was found. Logs: {}".format(cm.output), + ) + + def test_unique_violation_sets_deserialization_exception(self): + """At least one conflicting record should have deserialization_exception set.""" + self._create_conflicting_user_store_records() + + self.mc.deserialize_from_store() + + # At least one Store record should have deserialization_exception set + errored_stores = Store.objects.filter( + id__in=[self.user1_id, self.user2_id], + deserialization_exception__isnull=False, + ) + self.assertGreater( + errored_stores.count(), + 0, + "Expected at least one Store record to have deserialization_exception " + "set for unique constraint violation, but none did.", + ) + + # Verify the exception is a fully-qualified class path + for store in errored_stores: + self.assertEqual( + "django.db.utils.IntegrityError", + store.deserialization_exception, + "Expected deserialization_exception to be a fully-qualified class path like 'module.ClassName', got: {}".format( + store.deserialization_exception + ), + ) + + def test_non_conflicting_records_still_deserialize(self): + """Records that don't conflict should still be deserialized even when others conflict.""" + self._create_conflicting_user_store_records() + + ok_user_id = uuid.uuid4().hex + ok_user = MyUser(id=ok_user_id, username="noconflict", password="password") + StoreModelFacilityFactory( + id=ok_user_id, + serialized=json.dumps(ok_user.serialize()), + model_name="user", + ) + + self.mc.deserialize_from_store() + + self.assertTrue(MyUser.objects.filter(id=ok_user_id, username="noconflict").exists()) + + ok_store = Store.objects.get(id=ok_user_id) + self.assertFalse(ok_store.dirty_bit) + self.assertIsNone(ok_store.deserialization_error) + + class SelfReferentialFKDeserializationTestCase(TestCase): def setUp(self): self.current_id, _ = InstanceIDModel.get_or_create_current_instance() @@ -657,7 +803,7 @@ def test_deserialization_of_model_with_allowed_null_foreignkey(self): new_log.refresh_from_db() self.assertFalse(new_log.dirty_bit) - self.assertTrue(new_log.deserialization_error == "") + self.assertIsNone(new_log.deserialization_error) self.assertTrue(InteractionLog.objects.filter(id=new_log.id).exists()) def test_deserialization_of_model_with_valid_foreignkey_referent(self): @@ -677,7 +823,7 @@ def test_deserialization_of_model_with_valid_foreignkey_referent(self): new_log.refresh_from_db() self.assertFalse(new_log.dirty_bit) - self.assertTrue(new_log.deserialization_error == "") + self.assertIsNone(new_log.deserialization_error) self.assertTrue(SummaryLog.objects.filter(id=new_log.id).exists()) diff --git a/tests/testapp/tests/sync/test_operations.py b/tests/testapp/tests/sync/test_operations.py index 4c86c980..c07b39ba 100644 --- a/tests/testapp/tests/sync/test_operations.py +++ b/tests/testapp/tests/sync/test_operations.py @@ -1216,3 +1216,27 @@ def test_deserialization__conditional__with_filter(self): ) conditional_log = ConditionalLog.objects.get(pk=self.serialized_conditional["id"]) self.assertIsNone(conditional_log.user_id) + + def test_deserialization__skip_erroring(self): + self.serialize_all_to_store() + conditional_log_store = Store.objects.get(pk=self.serialized_conditional["id"]) + conditional_log_store.deserialization_error = ( + "AssertionError: this should not be deserialized!" + ) + conditional_log_store.save() + + _deserialize_from_store(self.profile, skip_erroring=True) + + self.assert_deserialization( + conditional_deserialized=False, + ) + + def test_deserialization__skip_erroring__empty_string(self): + self.serialize_all_to_store() + conditional_log_store = Store.objects.get(pk=self.serialized_conditional["id"]) + conditional_log_store.deserialization_error = "" + conditional_log_store.save() + + _deserialize_from_store(self.profile, skip_erroring=True) + + self.assert_deserialization() diff --git a/tests/testapp/tests/test_migrations.py b/tests/testapp/tests/test_migrations.py deleted file mode 100644 index fdf80cc8..00000000 --- a/tests/testapp/tests/test_migrations.py +++ /dev/null @@ -1,83 +0,0 @@ -import uuid - -import pytest -from django.conf import settings -from django.db import connection -from django.db.utils import IntegrityError -from django.test import TestCase, TransactionTestCase -from django.utils import timezone - -from .helpers import TestMigrationsMixin - - -@pytest.mark.skipif(not settings.MORANGO_TEST_POSTGRESQL, reason="Only postgres") -class MorangoNullableMigrationTest(TestMigrationsMixin, TestCase): - """ - Test migration that applies nullable status to `transfer_stage` and `transfer_stage_status` - """ - - app = "morango" - migrate_from = "0018_auto_20210714_2216" - migrate_to = "0020_postgres_fix_nullable" - - def setUpBeforeMigration(self, apps): - # simulate as if 0018_auto_20210714_2216 hadn't applied Nullablity to the columns, - # a change which we added after the migration might have run on other - SyncSession = apps.get_model("morango", "SyncSession") - - with connection.cursor() as cursor: - cursor.execute( - "ALTER TABLE morango_transfersession ALTER COLUMN transfer_stage SET NOT NULL" - ) - cursor.execute( - "ALTER TABLE morango_transfersession ALTER COLUMN transfer_stage_status SET NOT NULL" - ) - - self.sync_session = SyncSession.objects.create( - id=uuid.uuid4().hex, - profile="facilitydata", - last_activity_timestamp=timezone.now(), - ) - - def test_nullable(self): - TransferSession = self.apps.get_model("morango", "TransferSession") - - try: - transfer_session = TransferSession.objects.create( - id=uuid.uuid4().hex, - sync_session_id=self.sync_session.id, - push=True, - last_activity_timestamp=timezone.now(), - transfer_stage=None, - transfer_stage_status=None, - ) - except IntegrityError: - self.fail("Couldn't create TransferSession with nullable fields") - - self.assertIsNone(transfer_session.transfer_stage) - self.assertIsNone(transfer_session.transfer_stage_status) - - -@pytest.mark.skipif(not settings.MORANGO_TEST_POSTGRESQL, reason="Only postgres") -class SkipIfExistsMigrationTest(TestMigrationsMixin, TransactionTestCase): - """ - Test migration that creates an index on the partition field of the Store model - """ - - app = "morango" - migrate_from = "0020_postgres_fix_nullable" - migrate_to = "0021_store_partition_index_create" - - def setUpBeforeMigration(self, apps): - # simulate as if we already created an index on the partition field of the Store model - with connection.cursor() as cursor: - cursor.execute( - 'CREATE INDEX "idx_morango_store_partition" ON "morango_store" ("partition" text_pattern_ops);' - ) - - def test_runs(self): - """ - A dummy test, as the main point here is to make sure that the migration runs properly - with the index already existing - """ - self.assertTrue(True) diff --git a/tests/testapp/tests/test_utils.py b/tests/testapp/tests/test_utils.py index 782c5b64..f997ef9b 100644 --- a/tests/testapp/tests/test_utils.py +++ b/tests/testapp/tests/test_utils.py @@ -2,6 +2,7 @@ import mock import pytest +from django.db import IntegrityError from django.http.request import HttpRequest from django.test.testcases import SimpleTestCase from facility_profile.models import Facility, MyUser @@ -13,11 +14,15 @@ ASYNC_OPERATIONS, FSIC_V2_FORMAT, ) +from morango.errors import ( + MorangoDatabaseError, +) from morango.utils import ( CAPABILITIES_CLIENT_HEADER, SETTINGS, _posix_pid_exists, _windows_pid_exists, + exception_path, get_capabilities, parse_capabilities_from_server_request, pid_exists, @@ -121,3 +126,24 @@ class SelfReferentialFKTestCase(SimpleTestCase): def test_self_ref_fk(self): self.assertEqual(self_referential_fk(Facility), "parent_id") self.assertEqual(self_referential_fk(MyUser), None) + + +class ExceptionPathTestCase(SimpleTestCase): + def test_with_instance(self): + exc = ValueError("test") + self.assertEqual(exception_path(exc), "builtins.ValueError") + exc = IntegrityError("test") + self.assertEqual(exception_path(exc), "django.db.utils.IntegrityError") + + def test_with_class(self): + self.assertEqual(exception_path(TypeError), "builtins.TypeError") + self.assertEqual(exception_path(IntegrityError), "django.db.utils.IntegrityError") + + def test_with_custom_exception(self): + self.assertEqual( + exception_path(MorangoDatabaseError), "morango.errors.MorangoDatabaseError" + ) + self.assertEqual( + exception_path(MorangoDatabaseError("test")), + MorangoDatabaseError.path(), + )