Let the row refuse the write both kiosks were deciding in Python

Wave 1 of the remediation plan for the 2026-09-03 feature test run. Two kiosks,
one shape of defect, one critical consequence.

Both kiosks read the state, decided in Python, and then wrote. Nothing stops two
requests interleaving between the read and the write, so both see the same
pre-state and both proceed. Reproduced on MySQL 5.6 over HTTP, five concurrent
takes of 5 from a bin holding 5: all five were accepted and quantityonhand
landed on -20, because each request wrote its own arithmetic. The ledger had
recorded every one of them, so the cached quantity and the ledger disagreed
permanently, which is the number the shop floor actually reads. The USB kiosk
had the same shape: concurrent scans of one drive all succeeded and inserted
several open custody rows, so one drive was recorded out to two people and the
documented 409 never fired.

The comparison now lives in the WHERE clause, where the database settles it at
write time. printedparts._move_quantity issues
UPDATE ... WHERE quantityonhand >= :n and treats rowcount 0 as the refusal,
raising InsufficientStock, which take and adjust turn back into the message they
already gave - carrying the quantity the database holds now, not the stale one
the request read. The low-stock alert derives its before-value from what the
write produced for the same reason. Both USB paths claim the device with
ischeckedout (self-hosted) or status (external cmmc_usb) in the WHERE clause;
the external one claims BEFORE writing the log line, so a refused claim leaves
nothing to undo. Check-in is guarded the same way.

After the fix, the same five concurrent takes: one accepted, four refused,
quantityonhand 0 and the ledger sum 0.

Check-in also closes EVERY open row for the device rather than the newest.
One device can only be out once, so a second open row is corruption, and
closing only the newest left the older ones open forever - the device then read
as returned while its custody history said otherwise.

Separately, usbcheckouts now records who handed a drive back
(checkinsso/checkinname, migration usb0004checkinidentity). Returning for a
colleague is a supported flow that the kiosk asks to confirm, but the row it
wrote attributed the check-in to the HOLDER, so the custody history and the
audit report both named somebody who was not there. Nullable and deliberately
not backfilled: copying the holder's badge into old rows would manufacture
evidence for the exact claim this stops making.

Four tests. Both guards verified by planting: strip the condition out of either
UPDATE and its test fails.

Scope: product
This commit is contained in:
cproudlock
2026-09-03 13:58:26 -04:00
parent 377cc69264
commit aa8028f96e
8 changed files with 362 additions and 23 deletions

View File

@@ -257,6 +257,52 @@ from ..models import PrintedItemTransaction
from ..services.badges import BadgeError, resolve_badge
class InsufficientStock(Exception):
"""A decrement was refused because the row no longer holds that many.
Carries the quantity the DATABASE holds, not the stale one the caller read,
so the message the operator sees is the truth at the moment of the write.
"""
def __init__(self, available):
super().__init__('insufficient stock')
self.available = available
def _move_quantity(item, quantitychange):
"""Move quantityonhand by quantitychange in ONE statement, and let the row
itself refuse a decrement it cannot cover.
This is the guard, not the caller's earlier `quantity > item.quantityonhand`
check. That check reads, decides in Python, and writes - so two kiosk takes
that interleave both read the same on-hand figure and both pass it. Five
concurrent takes of 5 from a bin holding 5 all succeeded, each wrote its own
5 - 5 = 0, and quantityonhand ended up permanently out of step with the
ledger that recorded all five.
Expressing it as `UPDATE ... WHERE quantityonhand >= :n` makes the database
do the comparing at write time, where it is atomic. A row that no longer
holds enough matches nothing, rowcount is 0, and the take is refused.
Returns the resulting quantity.
"""
query = PrintedItem.query.filter(
PrintedItem.printeditemid == item.printeditemid)
if quantitychange < 0:
query = query.filter(PrintedItem.quantityonhand >= -quantitychange)
moved = query.update(
{PrintedItem.quantityonhand:
PrintedItem.quantityonhand + quantitychange},
synchronize_session=False)
if not moved:
# Read back what is actually there so the refusal can say so.
db.session.rollback()
available = db.session.query(PrintedItem.quantityonhand).filter(
PrintedItem.printeditemid == item.printeditemid).scalar() or 0
raise InsufficientStock(available)
db.session.refresh(item)
return item.quantityonhand
def _ledger_write(item, transactiontype, quantitychange, sso, name, reason=None,
revision=None):
"""Append a ledger row and move the cached quantity in ONE commit.
@@ -266,9 +312,17 @@ def _ledger_write(item, transactiontype, quantitychange, sso, name, reason=None,
alert when this write CROSSES the item's threshold downward - crossing
(not being below) is the natural debounce: one alert per depletion, and
restocking above the threshold rearms it.
Raises InsufficientStock when the row cannot cover the decrement. The
caller has already refused the obvious case; this is the one that only
shows up under concurrency.
"""
quantitybefore = item.quantityonhand
item.quantityonhand += quantitychange
# Derived from what the write ACTUALLY produced, not from what this request
# read earlier. Under concurrency the two differ, and the threshold
# crossing has to be judged on the real numbers or the alert fires for the
# wrong take (or not at all).
quantityafter = _move_quantity(item, quantitychange)
quantitybefore = quantityafter - quantitychange
db.session.add(PrintedItemTransaction(
printeditemid=item.printeditemid,
transactiontype=transactiontype,
@@ -427,7 +481,13 @@ def adjust_item(item_id: int):
except BadgeError as badge_error:
return error_response(ErrorCodes.VALIDATION_ERROR, str(badge_error),
http_code=422)
_ledger_write(item, 'adjust', quantitychange, sso, name, reason=reason)
try:
_ledger_write(item, 'adjust', quantitychange, sso, name, reason=reason)
except InsufficientStock as shortfall:
return error_response(
ErrorCodes.VALIDATION_ERROR,
f'Adjustment would drive stock below zero '
f'(on hand: {shortfall.available})')
return success_response(item.to_dict(), message='Stock adjusted')
@@ -579,7 +639,16 @@ def kiosk_take():
except (ValueError, TypeError):
revision = None
_ledger_write(item, 'take', -quantity, sso, name, revision=revision)
try:
_ledger_write(item, 'take', -quantity, sso, name, revision=revision)
except InsufficientStock as shortfall:
# Another kiosk took the last of it between this request's read and its
# write. Same message as the pre-check, with the number the database
# actually holds now.
return error_response(
ErrorCodes.VALIDATION_ERROR,
f'Only {shortfall.available} on hand - take fewer or see the '
f'parts team')
return success_response(item.to_dict(),
message=f'Took {quantity}, {item.quantityonhand} left')

View File

@@ -993,16 +993,30 @@ def kiosk_checkout():
'Badge not recognized - see IT to check this device out',
http_code=422)
# Claim the device FIRST, and let the status transition be the
# guard: the read-then-write above cannot stop two scans of the
# same drive that interleave, because both read 'available'. With
# the status in the WHERE clause the second UPDATE matches no row
# and there is no log entry to undo.
cur.execute(
'UPDATE devices SET status = %s '
'WHERE device_id = %s AND status <> %s',
(_STATUS_CHECKED_OUT, device_id, _STATUS_CHECKED_OUT),
)
if not cur.rowcount:
holder = _kiosk_holder_name(cur, device_id)
conn.rollback()
return error_response(
ErrorCodes.CONFLICT,
'That device is already checked out{}'.format(
' to {}'.format(holder) if holder else ''),
http_code=409)
cur.execute(
'INSERT INTO checkinoutlog '
'(badge_number, device_id, action, timestamp, locker_location) '
"VALUES (%s, %s, 'check-out', %s, %s)",
(badge, device_id, _now(), device.get('locker_location')),
)
cur.execute(
'UPDATE devices SET status = %s WHERE device_id = %s',
(_STATUS_CHECKED_OUT, device_id),
)
conn.commit()
finally:
conn.close()

View File

@@ -387,12 +387,34 @@ def kiosk_checkout(data):
http_code=422)
now = datetime.now(timezone.utc).replace(tzinfo=None)
# The transition IS the guard. The ischeckedout test above reads, decides
# in Python and then writes, so two kiosk scans of the same drive that
# interleave both read "available" and both insert a custody row - one
# drive recorded out to two people, and the documented 409 never fires.
# Making the flag part of the WHERE clause moves the decision into the
# write, where the database settles it: the second UPDATE matches no row.
claimed = USBDevice.query.filter(
USBDevice.usbdeviceid == device.usbdeviceid,
USBDevice.ischeckedout == False).update(
{USBDevice.ischeckedout: True,
USBDevice.currentuserid: badge,
USBDevice.currentusername: name,
USBDevice.currentcheckoutdate: now},
synchronize_session=False)
if not claimed:
db.session.rollback()
# Re-read the row rather than refreshing the object this request is
# holding: the whole point of arriving here is that the object is
# stale, and the caller deserves the name of whoever actually has it.
holder = db.session.query(USBDevice.currentusername).filter(
USBDevice.usbdeviceid == device.usbdeviceid).scalar()
return error_response(
ErrorCodes.CONFLICT,
'That device is already checked out{}'.format(
' to {}'.format(holder) if holder else ''),
http_code=409)
db.session.add(USBCheckout(usbdeviceid=device.usbdeviceid, sso=badge,
checkoutname=name, checkouttime=now))
device.ischeckedout = True
device.currentuserid = badge
device.currentusername = name
device.currentcheckoutdate = now
db.session.commit()
return success_response({'device_id': device.serialnumber,
'holdername': name},
@@ -439,15 +461,38 @@ def kiosk_checkin(data):
'holdername': device.currentusername or ''},
http_code=409)
open_checkout = (USBCheckout.query
.filter_by(usbdeviceid=device.usbdeviceid, checkintime=None)
.order_by(USBCheckout.checkouttime.desc()).first())
if open_checkout:
open_checkout.checkintime = datetime.now(timezone.utc).replace(tzinfo=None)
device.ischeckedout = False
device.currentuserid = None
device.currentusername = None
device.currentcheckoutdate = None
now = datetime.now(timezone.utc).replace(tzinfo=None)
# Guarded the same way as the checkout: only a device that is still out can
# be brought back, and the database decides that, not a Python read from
# earlier in this request.
released = USBDevice.query.filter(
USBDevice.usbdeviceid == device.usbdeviceid,
USBDevice.ischeckedout == True).update(
{USBDevice.ischeckedout: False,
USBDevice.currentuserid: None,
USBDevice.currentusername: None,
USBDevice.currentcheckoutdate: None},
synchronize_session=False)
if not released:
db.session.rollback()
return error_response(ErrorCodes.VALIDATION_ERROR,
'That device is not checked out')
# EVERY open row, not just the newest. One device can only be out once, so
# a second open row is corruption - closing only the newest one left the
# older ones open forever, and the device then reads as returned while its
# custody history says otherwise.
#
# checkinsso/checkinname record WHO HANDED IT BACK, which is not always the
# holder: returning for a colleague is a supported flow, and attributing
# the check-in to the holder made the audit trail name somebody who was not
# there.
(USBCheckout.query
.filter_by(usbdeviceid=device.usbdeviceid, checkintime=None)
.update({USBCheckout.checkintime: now,
USBCheckout.checkinsso: badge,
USBCheckout.checkinname: name},
synchronize_session=False))
db.session.commit()
return success_response({'device_id': device.serialnumber},
message='{} checked in'.format(device.serialnumber))

View File

@@ -0,0 +1,59 @@
"""Record who handed a drive back, not just when.
usbcheckouts held the checkout identity (sso, checkoutname) and, for the
return, only checkintime. Returning a drive for a colleague is a supported
kiosk flow - usb_kiosk_allow_return_for_others gates it and the kiosk asks for
confirmation - but the row it wrote attributed the check-in to the HOLDER. The
person who actually walked the drive back was recorded nowhere, so the custody
history and the audit report both named somebody who was not there.
Two columns rather than one: the badge is what the scanner emits and what joins
to a directory, and the name is what a report has to print when the directory
no longer resolves that badge.
Nullable, and not backfilled. A row closed before this column existed is one
where the returner was not recorded; copying the holder's badge into it would
manufacture evidence that the holder returned it, which is the exact claim this
migration exists to stop making.
Idempotent, so a re-run on an already-migrated database is a no-op.
Revision ID: usb0004checkinidentity
Revises: usb0003scanfields
"""
from alembic import op
import sqlalchemy as sa
revision = 'usb0004checkinidentity'
down_revision = 'usb0003scanfields'
branch_labels = None
depends_on = None
NEW_COLUMNS = (
('checkinsso', sa.String(length=20)),
('checkinname', sa.String(length=100)),
)
def upgrade():
bind = op.get_bind()
insp = sa.inspect(bind)
if 'usbcheckouts' not in insp.get_table_names():
return
cols = {c['name'] for c in insp.get_columns('usbcheckouts')}
for name, coltype in NEW_COLUMNS:
if name not in cols:
op.add_column('usbcheckouts',
sa.Column(name, coltype, nullable=True))
def downgrade():
bind = op.get_bind()
insp = sa.inspect(bind)
if 'usbcheckouts' not in insp.get_table_names():
return
cols = {c['name'] for c in insp.get_columns('usbcheckouts')}
for name, _ in NEW_COLUMNS:
if name in cols:
op.drop_column('usbcheckouts', name)

View File

@@ -128,6 +128,13 @@ class USBCheckout(BaseModel):
# Checkout details
checkouttime = db.Column(db.DateTime, nullable=False, default=_utcnow)
checkintime = db.Column(db.DateTime, nullable=True)
# WHO handed it back. Not always the holder: returning for a colleague is a
# supported flow, and recording the check-in against the holder named
# somebody who was not there. See migration usb0004checkinidentity.
checkinsso = db.Column(db.String(20), nullable=True,
comment='SSO of whoever returned it')
checkinname = db.Column(db.String(100), nullable=True,
comment='Name of whoever returned it')
# Metadata
checkoutreason = db.Column(db.Text, nullable=True, comment='Reason for checkout')

View File

@@ -72,8 +72,9 @@ EXPECTED_HEAD_REVISION['machines'] = 'machines0002rename'
EXPECTED_HEAD_REVISION['employees'] = 'employees0002photo'
# usb drops the dead usbcheckouts.machineid column on top of its anchor, then
# adds scannedviruses so an imported external history keeps the scan result -
# the field a removable-media audit actually asks about.
EXPECTED_HEAD_REVISION['usb'] = 'usb0003scanfields'
# the field a removable-media audit actually asks about - and finally records
# who handed a drive back, which is not always who took it out.
EXPECTED_HEAD_REVISION['usb'] = 'usb0004checkinidentity'
# network links a device to a catalog model, which is where its photo comes
# from - machines, PCs and printers already had that link.
EXPECTED_HEAD_REVISION['network'] = 'network0003prefix'

View File

@@ -532,3 +532,65 @@ def test_the_badge_route_is_not_an_enumeration_oracle(client, item, auth_headers
assert unknown.status_code == malformed.status_code == 422
assert (unknown.get_json()['data']['error']['message']
== malformed.get_json()['data']['error']['message'])
# --- the race ---------------------------------------------------------------
#
# The take read quantityonhand, compared it in Python, and then wrote. Five
# concurrent takes of 5 from a bin holding 5 all passed that comparison and all
# wrote their own 5 - 5 = 0, so quantityonhand ended up permanently out of step
# with the ledger that had recorded every one of them. The comparison now lives
# in the UPDATE's WHERE clause, where it is atomic.
def test_a_take_that_passed_its_precheck_is_still_refused_by_the_row(
client, auth_headers, app, item, directory_employee, kiosk,
monkeypatch):
"""Simulate the race window: the request holds an item that says 5 on hand
while the row has already been emptied by somebody else."""
from plugins.printedparts.api import routes
from plugins.printedparts.models import PrintedItem
stocked = client.post(f'/api/printedparts/items/{item}/restock',
json={'quantity': 5, 'badge': directory_employee},
headers=auth_headers)
assert stocked.status_code == 200
real_find = routes._kiosk_find_item
def stale_find(itemcode):
"""What the losing request sees: its own read, taken before the winner
committed, still shows a full bin.
Detached first, so setting the attribute changes only this request's
view and never reaches the database - the test is about a stale
reader, not about a second writer.
"""
found = real_find(itemcode)
if found is not None:
db.session.expunge(found)
found.quantityonhand = 5
return found
# Somebody else empties the bin first, through the kiosk, so the ledger
# records it the way a real competing take would.
winner = client.post('/api/printedparts/kiosk/take',
json={'itemcode': '3DP-9001', 'quantity': 5,
'badge': directory_employee},
headers=KIOSK_HEADERS)
assert winner.status_code == 200, winner.get_json()
monkeypatch.setattr(routes, '_kiosk_find_item', stale_find)
taken = client.post('/api/printedparts/kiosk/take',
json={'itemcode': '3DP-9001', 'quantity': 5,
'badge': directory_employee},
headers=KIOSK_HEADERS)
assert taken.status_code == 400, taken.get_json()
assert 'on hand' in taken.get_json()['data']['error']['message']
with app.app_context():
after = db.session.query(PrintedItem).filter_by(
printeditemid=item).first()
assert after.quantityonhand == 0, 'stock must not go negative'
ledger = sum(t.quantitychange for t in after.transactions)
assert ledger == after.quantityonhand, \
'quantityonhand and the ledger must agree'

View File

@@ -314,3 +314,85 @@ def test_the_token_alone_is_not_enough_when_the_kiosk_is_off(client, kiosk):
_setting(kiosk, 'usb_kiosk_enabled', 'false')
assert client.get('/api/usb/kiosk/device/USB-1',
headers=KIOSK_HEADERS).status_code == 404
# --- the race, and who returned it ------------------------------------------
#
# The kiosk decided "is this drive available?" in Python and then wrote. Two
# scans of the same drive that interleaved both read "available", so both
# inserted a custody row: one drive recorded out to two people, and the
# documented 409 never fired. The fix puts ischeckedout in the WHERE clause, so
# the database settles it at write time.
def test_a_checkout_that_passed_its_availability_check_is_still_refused(
client, kiosk, monkeypatch):
"""Simulate the race window: the request holds a device object that says
available while the row has already been claimed by somebody else."""
from plugins.usb.api import selfhosted
from plugins.usb.models import USBDevice
first = _out(client, badge='270015376')
assert first.status_code == 200
# What the losing request sees: its own read, taken before the winner
# committed, still says the drive is on the shelf.
stale = USBDevice.query.filter_by(serialnumber='USB-1').first()
monkeypatch.setattr(
selfhosted, '_find',
lambda device_id: _stale_copy(stale))
second = _out(client, badge='270099999')
assert second.status_code == 409, second.get_json()
open_rows = _open_checkouts(USBDevice)
assert len(open_rows) == 1, 'one drive, one open custody row'
assert open_rows[0].sso == '270015376'
def _stale_copy(device):
"""A detached stand-in that still believes the drive is available."""
class Stale:
usbdeviceid = device.usbdeviceid
serialnumber = device.serialnumber
isactive = True
ischeckedout = False
currentuserid = None
currentusername = None
return Stale()
def _open_checkouts(_):
from plugins.usb.models import USBCheckout
return USBCheckout.query.filter_by(checkintime=None).all()
def test_a_return_records_who_handed_it_back_not_only_the_holder(client, kiosk):
"""Returning for a colleague is a supported flow, so the check-in has to
name the person who actually walked it back."""
from plugins.usb.models import USBCheckout
assert _out(client, badge='270015376').status_code == 200
returned = _in(client, badge='270099999', forsomeoneelse=True)
assert returned.status_code == 200, returned.get_json()
row = USBCheckout.query.order_by(USBCheckout.checkoutid.desc()).first()
assert row.sso == '270015376', 'the holder still owns the checkout'
assert row.checkinsso == '270099999', 'the returner is recorded'
assert row.checkinname and 'Sam' in row.checkinname
def test_a_check_in_closes_every_open_row_for_that_device(client, kiosk, db):
"""Defence in depth for history written before the guard existed: a device
can only be out once, so a second open row is corruption, and closing only
the newest left the older ones open forever."""
from plugins.usb.models import USBCheckout, USBDevice
assert _out(client, badge='270015376').status_code == 200
device = USBDevice.query.filter_by(serialnumber='USB-1').first()
db.session.add(USBCheckout(usbdeviceid=device.usbdeviceid, sso='270099999',
checkoutname='Sam Okafor'))
db.session.commit()
assert len(_open_checkouts(USBDevice)) == 2
assert _in(client, badge='270015376').status_code == 200
assert _open_checkouts(USBDevice) == []