From 5d81f50c33e5228f985963004bc3d83b0bdec110 Mon Sep 17 00:00:00 2001 From: cproudlock Date: Thu, 3 Sep 2026 14:25:55 -0400 Subject: [PATCH] Stop the audit log from being what fails the write Wave 4, second half. PUT /api/machines/ 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 --- shopdb/core/models/auditlog.py | 351 +++++++++++--------- tests/test_core/test_strict_write_errors.py | 41 +++ tests/test_plugins/test_measuringtools.py | 33 ++ 3 files changed, 266 insertions(+), 159 deletions(-) diff --git a/shopdb/core/models/auditlog.py b/shopdb/core/models/auditlog.py index b397c854..642cc6fb 100644 --- a/shopdb/core/models/auditlog.py +++ b/shopdb/core/models/auditlog.py @@ -1,159 +1,192 @@ -"""Audit log model for tracking changes.""" - -from datetime import datetime, timezone -from shopdb.extensions import db - -def _utcnow(): - # naive UTC for DB columns (stored without tzinfo) - return datetime.now(timezone.utc).replace(tzinfo=None) - - -class AuditLog(db.Model): - """ - Audit log for tracking user actions. - - Records who did what, when, from where, and what changed. - """ - __tablename__ = 'auditlogs' - - auditlogid = db.Column(db.Integer, primary_key=True) - - # Who - userid = db.Column(db.Integer, db.ForeignKey('users.userid'), nullable=True) - username = db.Column(db.String(100), nullable=True) # Denormalized for history - - # When - timestamp = db.Column(db.DateTime, default=_utcnow, nullable=False, index=True) - - # Where (client info) - ipaddress = db.Column(db.String(45), nullable=True) # IPv6 max length - useragent = db.Column(db.String(255), nullable=True) - - # What - action = db.Column(db.String(20), nullable=False, index=True) # created, updated, deleted - entitytype = db.Column(db.String(50), nullable=False, index=True) # Asset, Printer, Setting, etc. - entityid = db.Column(db.Integer, nullable=True) # ID of the affected record - entityname = db.Column(db.String(255), nullable=True) # Human-readable identifier - - # Changes (stored as JSON text) - _changes = db.Column('changes', db.Text, nullable=True) # {"field": {"old": x, "new": y}, ...} - - @property - def changes(self): - """Get changes as dict.""" - if self._changes: - import json - try: - return json.loads(self._changes) - except (json.JSONDecodeError, TypeError): - return None - return None - - @changes.setter - def changes(self, value): - """Set changes from dict.""" - if value is not None: - import json - self._changes = json.dumps(value) - else: - self._changes = None - - # Additional context - details = db.Column(db.Text, nullable=True) # Optional description - - # Relationship - user = db.relationship('User', backref=db.backref('auditlogs', lazy='dynamic')) - - def to_dict(self): - return { - 'auditlogid': self.auditlogid, - 'userid': self.userid, - 'username': self.username, - 'timestamp': self.timestamp.isoformat() + 'Z' if self.timestamp else None, - 'ipaddress': self.ipaddress, - 'useragent': self.useragent, - 'action': self.action, - 'entitytype': self.entitytype, - 'entityid': self.entityid, - 'entityname': self.entityname, - 'changes': self.changes, - 'details': self.details - } - - @classmethod - def log(cls, action: str, entitytype: str, entityid: int = None, - entityname: str = None, changes: dict = None, details: str = None, - user=None, request=None): - """ - Create an audit log entry. - - Args: - action: 'created', 'updated', 'deleted' - entitytype: Type of entity (e.g., 'Asset', 'Printer', 'Setting') - entityid: ID of the affected record - entityname: Human-readable name/identifier - changes: Dict of field changes {"field": {"old": x, "new": y}} - details: Optional description - user: Current user object (or will try to get from flask-jwt-extended) - request: Flask request object (or will try to get current request) - """ - from flask import request as flask_request - from flask_jwt_extended import current_user, verify_jwt_in_request - - # Get user info - if user is None: - try: - verify_jwt_in_request(optional=True) - user = current_user - except: - pass - - userid = user.userid if user else None - username = user.username if user else None - - # Get request info - request_obj = request or flask_request - ipaddress = None - useragent = None - - if request_obj: - # First-hop client IP, port stripped (ARR forwards clientip:port). - from shopdb.utils.clientip import client_ip - ipaddress = client_ip(request_obj) - useragent = request_obj.headers.get('User-Agent', '')[:255] - - entry = cls( - userid=userid, - username=username, - ipaddress=ipaddress, - useragent=useragent, - action=action, - entitytype=entitytype, - entityid=entityid, - entityname=entityname, - changes=changes, - details=details - ) - - db.session.add(entry) - # Don't commit here - let the caller handle transaction - return entry - - @classmethod - def log_create(cls, entitytype: str, entity, name_field: str = 'name'): - """Log a create action.""" - entityname = getattr(entity, name_field, None) or str(entity) - entityid = getattr(entity, f'{entitytype.lower()}id', None) or getattr(entity, 'id', None) - return cls.log('created', entitytype, entityid=entityid, entityname=entityname) - - @classmethod - def log_update(cls, entitytype: str, entity, changes: dict, name_field: str = 'name'): - """Log an update action with changes.""" - entityname = getattr(entity, name_field, None) or str(entity) - entityid = getattr(entity, f'{entitytype.lower()}id', None) or getattr(entity, 'id', None) - return cls.log('updated', entitytype, entityid=entityid, entityname=entityname, changes=changes) - - @classmethod - def log_delete(cls, entitytype: str, entityid: int, entityname: str = None): - """Log a delete action.""" - return cls.log('deleted', entitytype, entityid=entityid, entityname=entityname) +"""Audit log model for tracking changes.""" + +from datetime import datetime, timezone +from shopdb.extensions import db + +def _utcnow(): + # naive UTC for DB columns (stored without tzinfo) + 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. + + Records who did what, when, from where, and what changed. + """ + __tablename__ = 'auditlogs' + + auditlogid = db.Column(db.Integer, primary_key=True) + + # Who + userid = db.Column(db.Integer, db.ForeignKey('users.userid'), nullable=True) + username = db.Column(db.String(100), nullable=True) # Denormalized for history + + # When + timestamp = db.Column(db.DateTime, default=_utcnow, nullable=False, index=True) + + # Where (client info) + ipaddress = db.Column(db.String(45), nullable=True) # IPv6 max length + useragent = db.Column(db.String(255), nullable=True) + + # What + action = db.Column(db.String(20), nullable=False, index=True) # created, updated, deleted + entitytype = db.Column(db.String(50), nullable=False, index=True) # Asset, Printer, Setting, etc. + entityid = db.Column(db.Integer, nullable=True) # ID of the affected record + entityname = db.Column(db.String(255), nullable=True) # Human-readable identifier + + # Changes (stored as JSON text) + _changes = db.Column('changes', db.Text, nullable=True) # {"field": {"old": x, "new": y}, ...} + + @property + def changes(self): + """Get changes as dict.""" + if self._changes: + import json + try: + return json.loads(self._changes) + except (json.JSONDecodeError, TypeError): + return None + return None + + @changes.setter + def changes(self, value): + """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/ 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, default=_jsonsafe) + else: + self._changes = None + + # Additional context + details = db.Column(db.Text, nullable=True) # Optional description + + # Relationship + user = db.relationship('User', backref=db.backref('auditlogs', lazy='dynamic')) + + def to_dict(self): + return { + 'auditlogid': self.auditlogid, + 'userid': self.userid, + 'username': self.username, + 'timestamp': self.timestamp.isoformat() + 'Z' if self.timestamp else None, + 'ipaddress': self.ipaddress, + 'useragent': self.useragent, + 'action': self.action, + 'entitytype': self.entitytype, + 'entityid': self.entityid, + 'entityname': self.entityname, + 'changes': self.changes, + 'details': self.details + } + + @classmethod + def log(cls, action: str, entitytype: str, entityid: int = None, + entityname: str = None, changes: dict = None, details: str = None, + user=None, request=None): + """ + Create an audit log entry. + + Args: + action: 'created', 'updated', 'deleted' + entitytype: Type of entity (e.g., 'Asset', 'Printer', 'Setting') + entityid: ID of the affected record + entityname: Human-readable name/identifier + changes: Dict of field changes {"field": {"old": x, "new": y}} + details: Optional description + user: Current user object (or will try to get from flask-jwt-extended) + request: Flask request object (or will try to get current request) + """ + from flask import request as flask_request + from flask_jwt_extended import current_user, verify_jwt_in_request + + # Get user info + if user is None: + try: + verify_jwt_in_request(optional=True) + user = current_user + except: + pass + + userid = user.userid if user else None + username = user.username if user else None + + # Get request info + request_obj = request or flask_request + ipaddress = None + useragent = None + + if request_obj: + # First-hop client IP, port stripped (ARR forwards clientip:port). + from shopdb.utils.clientip import client_ip + ipaddress = client_ip(request_obj) + useragent = request_obj.headers.get('User-Agent', '')[:255] + + entry = cls( + userid=userid, + username=username, + ipaddress=ipaddress, + useragent=useragent, + action=action, + entitytype=entitytype, + entityid=entityid, + entityname=entityname, + changes=changes, + details=details + ) + + db.session.add(entry) + # Don't commit here - let the caller handle transaction + return entry + + @classmethod + def log_create(cls, entitytype: str, entity, name_field: str = 'name'): + """Log a create action.""" + entityname = getattr(entity, name_field, None) or str(entity) + entityid = getattr(entity, f'{entitytype.lower()}id', None) or getattr(entity, 'id', None) + return cls.log('created', entitytype, entityid=entityid, entityname=entityname) + + @classmethod + def log_update(cls, entitytype: str, entity, changes: dict, name_field: str = 'name'): + """Log an update action with changes.""" + entityname = getattr(entity, name_field, None) or str(entity) + entityid = getattr(entity, f'{entitytype.lower()}id', None) or getattr(entity, 'id', None) + return cls.log('updated', entitytype, entityid=entityid, entityname=entityname, changes=changes) + + @classmethod + def log_delete(cls, entitytype: str, entityid: int, entityname: str = None): + """Log a delete action.""" + return cls.log('deleted', entitytype, entityid=entityid, entityname=entityname) diff --git a/tests/test_core/test_strict_write_errors.py b/tests/test_core/test_strict_write_errors.py index af8f1633..a0102238 100644 --- a/tests/test_core/test_strict_write_errors.py +++ b/tests/test_core/test_strict_write_errors.py @@ -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/ 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 '' + + entry = AuditLog() + entry.changes = {'thing': {'old': Odd(), 'new': None}} + assert entry.changes['thing']['old'] == '' diff --git a/tests/test_plugins/test_measuringtools.py b/tests/test_plugins/test_measuringtools.py index d6f5edcb..77c2ab3f 100644 --- a/tests/test_plugins/test_measuringtools.py +++ b/tests/test_plugins/test_measuringtools.py @@ -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/ 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'