Stop the audit log from being what fails the write

Wave 4, second half. PUT /api/machines/<id> returned 500 and rolled the whole
edit back for any machine with a maintenance date recorded - including a rename
that never touched the date. The Machine edit form could not save such a
machine at all, which is most of them once a maintenance schedule exists.

The route builds {'old': getattr(row, field)} straight off the model, so the
changes dict carries whatever the column holds: a date, a datetime, a Decimal.
AuditLog.changes serialised it with a bare json.dumps, which raises on all
three, and nothing caught it. The audit entry and the edit share a transaction,
so the failure took the edit with it.

json.dumps now has a fallback encoder: dates and datetimes become ISO strings,
Decimals become floats, sets and bytes get something readable, and anything
else becomes its repr rather than an exception. An audit entry that reads a
little awkwardly is worth more than a failed write - the alternative, and what
happened, is losing the change AND the record of it.

Fixed at the audit log rather than in the machines route: every audited route
builds its changes dict the same way, so the next one to audit a date field
would have hit the same wall.

Four tests, including the exact shape the machines route produces. Verified by
planting the bare dumps back: two fail.

Scope: product
This commit is contained in:
cproudlock
2026-09-03 14:25:55 -04:00
parent 13e992d863
commit 5d81f50c33
3 changed files with 266 additions and 159 deletions

View File

@@ -8,6 +8,28 @@ def _utcnow():
return datetime.now(timezone.utc).replace(tzinfo=None)
def _jsonsafe(value):
"""Last-resort encoder for a value the audit log was handed.
Dates and datetimes become ISO strings, Decimals become floats, and
anything else becomes its repr rather than an exception. An audit entry
that reads a little awkwardly is worth more than a failed write: the
alternative, and what happened, is losing the change AND the record of it.
"""
from datetime import date, datetime, time
from decimal import Decimal
if isinstance(value, (datetime, date, time)):
return value.isoformat()
if isinstance(value, Decimal):
return float(value)
if isinstance(value, (set, frozenset)):
return sorted(str(item) for item in value)
if isinstance(value, bytes):
return value.decode('utf-8', 'replace')
return repr(value)
class AuditLog(db.Model):
"""
Audit log for tracking user actions.
@@ -51,10 +73,21 @@ class AuditLog(db.Model):
@changes.setter
def changes(self, value):
"""Set changes from dict."""
"""Set changes from dict.
Serialised with a fallback for the types a model actually holds. A bare
json.dumps raises on a date, a datetime or a Decimal, and the caller is
a route building {'old': getattr(row, field)} straight off the model -
so the moment an audited field held a date, the whole request died.
That is not hypothetical: PUT /api/machines/<id> returned 500 and rolled
the edit back for ANY machine with a maintenance date recorded,
including a rename that never touched the date. The audit log refusing
to record a change must not be what stops the change.
"""
if value is not None:
import json
self._changes = json.dumps(value)
self._changes = json.dumps(value, default=_jsonsafe)
else:
self._changes = None

View File

@@ -97,3 +97,44 @@ def test_the_strict_sql_mode_is_actually_set_on_the_mysql_connection():
connect_args = Config.SQLALCHEMY_ENGINE_OPTIONS['connect_args']
assert 'STRICT_TRANS_TABLES' in connect_args['init_command']
# --- the audit log must never be what fails the write ------------------------
def test_audit_changes_serialise_the_types_a_model_actually_holds():
"""A route builds {'old': getattr(row, field)} straight off the model, so
the changes dict carries dates, datetimes and Decimals. json.dumps raises
on all three, and the exception took the whole request down: PUT
/api/machines/<id> 500d and rolled back for any machine with a maintenance
date, including a rename that never touched it."""
import datetime
import decimal
from shopdb.core.models.auditlog import AuditLog
entry = AuditLog()
entry.changes = {
'nextmaintenancedate': {'old': datetime.date(2026, 12, 15),
'new': '2027-01-05'},
'lastseen': {'old': datetime.datetime(2026, 1, 2, 3, 4, 5),
'new': None},
'cost': {'old': decimal.Decimal('12.50'), 'new': 13},
}
stored = entry.changes
assert stored['nextmaintenancedate']['old'] == '2026-12-15'
assert stored['lastseen']['old'] == '2026-01-02T03:04:05'
assert stored['cost']['old'] == 12.5
def test_an_unserialisable_value_is_recorded_rather_than_raising():
"""An audit entry that reads awkwardly beats a failed write: the
alternative is losing the change AND the record of it."""
from shopdb.core.models.auditlog import AuditLog
class Odd:
def __repr__(self):
return '<Odd value>'
entry = AuditLog()
entry.changes = {'thing': {'old': Odd(), 'new': None}}
assert entry.changes['thing']['old'] == '<Odd value>'

View File

@@ -553,3 +553,36 @@ def test_a_mistyped_date_is_refused_at_create_too(client, auth_headers):
listed = client.get('/api/measuringtools?search=MT-DATE-3',
headers=auth_headers).get_json()['data']
assert listed == [], 'nothing may be created by a refused request'
# --- an audited field holding a date must not kill the request ---------------
#
# PUT /api/machines/<id> returned 500 and rolled the whole edit back for any
# machine with a maintenance date: the route builds
# {'old': getattr(row, field)} straight off the model, and json.dumps raises on
# a date. A rename that never touched the date failed too. The audit log
# refusing to record a change must not be what stops the change.
def test_an_edit_is_saved_even_when_an_audited_field_holds_a_date(
client, auth_headers):
created = client.post('/api/measuringtools', headers=auth_headers, json={
'assetnumber': 'MT-AUDIT-1',
'name': 'Before rename',
'statusid': _status_id(client),
'lastcalibrationdate': '2026-01-15',
'nextcalibrationdate': '2027-01-15',
})
assert created.status_code == 201, created.get_json()
toolid = created.get_json()['data']['measuringtool']['measuringtoolid']
# A rename that does not touch the dates. The date is only in the CHANGES
# dict because the interval moves with it.
renamed = client.put(f'/api/measuringtools/{toolid}', headers=auth_headers,
json={'name': 'After rename',
'nextcalibrationdate': '2028-01-15'})
assert renamed.status_code == 200, renamed.get_json()
after = client.get(f'/api/measuringtools/{toolid}',
headers=auth_headers).get_json()['data']
assert after['name'] == 'After rename'
assert after['measuringtool']['nextcalibrationdate'] == '2028-01-15'