soynatan / django-easy-audit

Yet another Django audit log app, hopefully the simplest one.
GNU General Public License v3.0
720 stars 179 forks source link

Exception in pre_save signal when deleting object #135

Closed patrikrazem closed 4 years ago

patrikrazem commented 4 years ago

Django version: 2.2.11 and 3.0.5 Python version: 3.3.7 Django-easy-audit version: 1.2.1


The following error occurs when attempting to delete an object in a model for which CRUD audit log events are being recorded:

easy audit had a pre-save exception on CRUDEvent creation. instance: Third, instance pk: None
Traceback (most recent call last):
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute
    return self.cursor.execute(sql, params)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/sqlite3/base.py", line 396, in execute
    return Database.Cursor.execute(self, query, params)
sqlite3.IntegrityError: NOT NULL constraint failed: easyaudit_crudevent.object_id

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/easyaudit/signals/model_signals.py", line 301, in crud_flow
    user_pk_as_string=str(user.pk) if user else user
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/query.py", line 433, in create
    obj.save(force_insert=True, using=self.db)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/base.py", line 746, in save
    force_update=force_update, update_fields=update_fields)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/base.py", line 784, in save_base
    force_update, using, update_fields,
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/base.py", line 887, in _save_table
    results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/base.py", line 926, in _do_insert
    using=using, raw=raw,
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/manager.py", line 82, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/query.py", line 1204, in _insert
    return query.get_compiler(using=using).execute_sql(returning_fields)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1391, in execute_sql
    cursor.execute(sql, params)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 100, in execute
    return super().execute(sql, params)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 68, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 77, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute
    return self.cursor.execute(sql, params)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/utils.py", line 86, in _execute
    return self.cursor.execute(sql, params)
  File "/Users/patrik/projects/playground/easyaudit-sample/venv/lib/python3.7/site-packages/django/db/backends/sqlite3/base.py", line 396, in execute
    return Database.Cursor.execute(self, query, params)

I've created a minimal reproduction repo for this: https://github.com/patrikrazem/easyaudit-sample

As far as I can tell, when the object is deleted, an attempt is made to write a CRUDevent with an object_id with NULL value, because the instance has already been deleted.

Is this a bug in the way deletions are handled, or am I missing something (or doing something wrong)?

jheld commented 4 years ago

Hi, thank you for posting this

I don't have the code up right now, but agreed something seems wrong because indeed the object has not been deleted yet.

I wonder if we didn't have a deletion test case, or if as I assume the exception handler caught, logged, and moved on. We could alter the deletion test to watch for logs created (python or django testing does have tooling for that).

There can be a number of issues with deletion in general (I'm not implying that this issue is one of these), one of which being if you're deletion has a cascade and if the entity that's being deleted relies in some form (it's str or repr) on being able to display a value including data from a related (FK or M2M), that FK or M2M may have been deleted already and thus the CRUDEvent delete record will not succeed (and even the error logger may also fail, probably for the same reason). I may be crossing some wires here (code is in my head), but I just wanted to warn that deletion isn't perfect (both in the library and also via decisions made by the host app). Thank you for creating a sample repo, by the way. I'm going to see if I can look at this within the next week). Please ping me back here if I'm taking too long. My company does use this project so sometimes I'm able to make time during the work day.

Also just making sure, I think we have a new beta (I don't think I've released the official version but I expect it basically is official), would you be willing to upgrade to it if you're not already on it?

Also is this on pre-save or delete? Just want to make sure that the title is correct.

patrikrazem commented 4 years ago

There can be a number of issues with deletion in general (I'm not implying that this issue is one of these), one of which being if you're deletion has a cascade and if the entity that's being deleted relies in some form (it's str or repr) on being able to display a value including data from a related (FK or M2M), that FK or M2M may have been deleted already and thus the CRUDEvent delete record will not succeed (and even the error logger may also fail, probably for the same reason). I may be crossing some wires here (code is in my head), but I just wanted to warn that deletion isn't perfect (both in the library and also via decisions made by the host app). Thank you for creating a sample repo, by the way. I'm going to see if I can look at this within the next week). Please ping me back here if I'm taking too long. My company does use this project so sometimes I'm able to make time during the work day.

I realize that there might be many reasons and complicated scenarios why a delete might fail and that's exactly why I created a sample repo with the minimal possible complexity. It has just one model with one property -- no foreign keys, no relationships, no special configuration.

Also just making sure, I think we have a new beta (I don't think I've released the official version but I expect it basically is official), would you be willing to upgrade to it if you're not already on it?

I'm on django-easy-audit version 1.2.1 and I have not tested any beta releases yet.

Also is this on pre-save or delete? Just want to make sure that the title is correct.

I don't really understand why, but the exception occurs in the pre_save handler, as evident in my originally pasted stacktrace.

As far as I can tell:

  1. I delete an object from the Django admin console
  2. The object is deleted from the DB
  3. After the object is deleted, the library attempts to write a CRUDEvent entry in the DB, referencing the deleted object
  4. Before the CRUDEvent is written to the DB, the pre_save handler is executed, which recieves an instance of the deleted object. At this point, the instance (the deleted object) has a pk = NULL (since it's already been deleted and no longer exists in the DB).
  5. The write for the CRUDEvent fails, because CRUDEvent.object_id has a non-null constraint

It's not quite clear to me why the pre_save handler is executed before saving the CRUDEvent, but I'm guessing I simply don't sufficiently understand the process.

patrikrazem commented 4 years ago

Anything new on this front?

jheld commented 4 years ago

I'm sorry I haven't had time to debug further.

Please ping me in a week on here if still nothing.

patrikrazem commented 4 years ago

@jheld I'm guessing there's still nothing.

The easyaudit_crudevent table has an object_id field which is constrained to being NOT NULL. When you are storing a CRUD entry for creation and updates, that's simple -- because the object_id value references the object that was created/edited and is still present in the DB.

But when you delete the object that the CRUD event is referencing, it can't possibly have an object_id, because that object no longer exists in the DB. So, of course it doesn't work.

This seems to me to be more of a design decision regarding how the library will handle these scenarios. You could:

  1. Say that hard deletes are not supported at all and that objects should merely be soft-deleted (with a deleted flag, etc.) and always still persist in the DB
  2. Make the object_id field in the easyaudit_crudevent table NULLABLE and thus allow having CRUD event records that don't directly reference the deleted object
  3. Something else, I guess ....

To me it seems like the second option is the most logical one. But then again, I could be wrong.

jheld commented 4 years ago

This has been fixed and is available for on a pre-release version 1.3.0a3. There is a migration because of internal changes to object_id in the upcoming release but we also don't anticipate any issues.

Going to close this (thank you for opening the issue) since we have a fix in place for the upcoming release which is on PyPI.