FieldTracker infinite recursion on deleting object

[brianmay]

Problem

Call obj.delete() results in:

Fatal Python error: _Py_CheckRecursiveCall: Cannot recover from stack overflow.
Python runtime state: initialized

Current thread 0x00007f955a596280 (most recent call first):
  File "/home/brian/.asdf/installs/python/3.9.7/lib/python3.9/abc.py", line 119 in __instancecheck__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/sql/query.py", line 1443 in build_filter
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/sql/query.py", line 1562 in _add_q
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/sql/query.py", line 1532 in add_q
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query.py", line 1445 in _filter_or_exclude_inplace
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query.py", line 1438 in _filter_or_exclude
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query.py", line 1420 in filter
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/manager.py", line 85 in manager_method
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/base.py", line 724 in refresh_from_db
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 375 in inner
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query_utils.py", line 178 in __get__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 75 in __get__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 208 in get_field_value
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 234 in <dictcomp>
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 234 in current
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 216 in set_saved_fields
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 184 in __exit__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 375 in inner
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query_utils.py", line 178 in __get__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 75 in __get__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 208 in get_field_value
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 234 in <dictcomp>
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 234 in current
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 216 in set_saved_fields
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 184 in __exit__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py", line 375 in inner
  [...]

Environment

• Django Model Utils version: 4.2.0
• Django version: 4.1.1
• Python version: 3.9.7

[brianmay]

Hmm. Problem is related object has a foreign key to this object with on_delete=models.SET_NULL, so we need to set this value to None.

This happens in django/db/models/deletion.py line 505:

setattr(obj, field.attname, value)

Where obj points to instance of related object, field.attname is the name of the field, and value is None.

If I change the on_delete to models.CASCADE then it works.

If I change the on_delete to models.PROTECT then it fails, but earlier.

Will try to create a simple test case. Later.

[brianmay]

More information.

The __set__ method in tracker calls the __get__ method. This is what crashes. Bit puzzled why the stack trace does not include this.

The __set__ method has code to protect against infinite recursion. But this does not help, because the infinite recursion occurs in the __get__ method (see stack trace) not the __set__ method.

[brianmay]

Here is a better stack trace (I stopped after second call to __get__):.

-> institute.delete()
  /home/brian/tree/unimelb/karaage/karaage/karaage/institutes/models.py(102)delete()
-> super(Institute, self).delete(*args, **kwargs)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/base.py(1137)delete()
-> return collector.delete()
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/deletion.py(505)delete()
-> setattr(obj, field.attname, value)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(98)__set__()
-> getattr(instance, self.field_name)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(75)__get__()
-> value = self.descriptor.__get__(instance, owner)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/query_utils.py(178)__get__()
-> instance.refresh_from_db(fields=[field_name])
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(376)inner()
-> return original(instance, *args, **kwargs)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(184)__exit__()
-> self.tracker.set_saved_fields(fields=reset_fields)
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(216)set_saved_fields()
-> self.saved_data.update(**self.current(fields=fields))
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(234)current()
-> return {f: self.get_field_value(f) for f in fields}
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(234)<dictcomp>()
-> return {f: self.get_field_value(f) for f in fields}
  /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(208)get_field_value()
-> return getattr(self.instance, self.field_map[field])
> /home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/model_utils/tracker.py(70)__get__()
-> def __get__(self, instance, owner):

[brianmay]

1. We delete a database record.
2. This needs to set a field to NULL on a related object.
3. This calls the __set__ method, which is intercepted by tracker.
4. Tracker needs to know what the original value was. So it calls the __get__ method to get the original value.
5. This calls code inside Django, which eventually calls refresh_from_db to actually retrieve the values.
6. refresh_from_db is intercepted by tracker. We want to make sure when loading from the database, we save the values we retrieved as the original values. We load the values. And then call current in order retrieve the values, so we can save them.
7. Eventually we call __get__, which results in infinite recursion.

The reasoning behind each individual step makes sense, and is correct. But when you combine all these correct steps together, you get code that is obviously broken.

[brianmay]

Trying this library instead: https://pypi.org/project/django-tracking-model/

[chapimenge3]

@brianmay could you please write the step to reproduce the bug in detail ?

thank you.

[brianmay]

Will add creating a simple test case this to my to do list. But not a lot of time lately.

In the meantime this is the full code that caused the problem:

https://github.com/Karaage-Cluster/karaage/tree/field_tracking_broken

This is the field_tracking_broken branch.

$ poetry run python -m tldap.test.slapd pytest -x karaage/tests/institutes/test_models.py -k test_change_group -s
Starting slapd...
DEBUG:slapd:creating temp directory /tmp/brian/tmph2m7q1u3/ldif-data
DEBUG:Slapd:writing config to /tmp/brian/tmph2m7q1u3/slapd.conf
_#################### 100.00% eta   none elapsed            none fast!
Closing DB...
DEBUG:Slapd:testing configuration
config file testing succeeded
DEBUG:Slapd:configuration seems ok
INFO:Slapd:starting slapd
INFO:slapd:Found available port 55641
DEBUG:Slapd:Connecting to ('127.0.0.1', 55641)
DEBUG:Slapd:Connecting to ('127.0.0.1', 55641)
DEBUG:Slapd:slapd ready at ldap://127.0.0.1:55641/
Contents of LDAP server follow:

DEBUG:Slapd:ldapsearch filter='(objectClass=*)'
dn: dc=python-ldap,dc=org
dc: python-ldap
o: python-ldap
objectClass: dcObject
objectClass: organization

dn: cn=Manager,dc=python-ldap,dc=org
cn: Manager
objectClass: simpleSecurityObject
objectClass: organizationalRole

dn: cn=default,dc=python-ldap,dc=org
objectClass: top
objectClass: device
objectClass: pwdPolicy
pwdAttribute: userPassword
pwdLockout: TRUE
cn: default

dn: ou=People,dc=python-ldap,dc=org
objectClass: top
objectClass: OrganizationalUnit
ou: People

dn: ou=Groups,dc=python-ldap,dc=org
objectClass: top
objectClass: OrganizationalUnit
ou: Groups

Running command ['pytest', '-x', 'karaage/tests/institutes/test_models.py', '-k', 'test_change_group', '-s']...
===================================================================== test session starts =====================================================================
platform linux -- Python 3.9.7, pytest-7.1.3, pluggy-1.0.0
django: settings: karaage.tests.settings (from ini)
rootdir: /home/brian/tree/unimelb/karaage/karaage, configfile: pytest.ini
plugins: django-4.5.2, cov-3.0.0, Faker-14.2.0
collected 4 items / 3 deselected / 1 selected

karaage/tests/institutes/test_models.py Fatal Python error: _Py_CheckRecursiveCall: Cannot recover from stack overflow.
Python runtime state: initialized

Current thread 0x00007f0160a26280 (most recent call first):
  File "/home/brian/.asdf/installs/python/3.9.7/lib/python3.9/abc.py", line 119 in __instancecheck__
[...]

Note:

• This requires a copy of slapd. No configuration required, just need access to the binary. The tests will configure an instance on the fly.
• The stack trace produced, while correct, is missing entries that are clearly shown if I stop code execution in the debugger and show the stack trace.

[brianmay]

Actually never mind, slapd not required, this is simpler:

Will leave the previous version with slapd just in case it helps.

$ poetry install
[...]
$ poetry run pytest -x karaage/tests/institutes/test_models.py -k test_change_group -s
===================================================================== test session starts =====================================================================
platform linux -- Python 3.9.7, pytest-7.1.3, pluggy-1.0.0
django: settings: karaage.tests.settings (from ini)
rootdir: /home/brian/tree/unimelb/karaage/karaage, configfile: pytest.ini
plugins: django-4.5.2, cov-3.0.0, Faker-14.2.0
collected 4 items / 3 deselected / 1 selected

karaage/tests/institutes/test_models.py Fatal Python error: _Py_CheckRecursiveCall: Cannot recover from stack overflow.
Python runtime state: initialized

Current thread 0x00007f9ec497c280 (most recent call first):
  File "/home/brian/.asdf/installs/python/3.9.7/lib/python3.9/abc.py", line 119 in __instancecheck__
  File "/home/brian/.cache/pypoetry/virtualenvs/karaage-uhi1oUwy-py3.9/lib/python3.9/site-packages/django/db/models/sql/query.py", line 1443 in build_filter
[...]

[hendrikschneider]

any update here?

[nick-prat]

I believe I found a fix for this here: https://github.com/jazzband/django-model-utils/pull/620