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
@@ -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/<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, 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)
|
||||
|
||||
@@ -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>'
|
||||
|
||||
@@ -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'
|
||||
|
||||
Reference in New Issue
Block a user