diff --git a/plugins/printedparts/api/routes.py b/plugins/printedparts/api/routes.py index 682d9add..be6191ba 100644 --- a/plugins/printedparts/api/routes.py +++ b/plugins/printedparts/api/routes.py @@ -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') diff --git a/plugins/usb/api/routes.py b/plugins/usb/api/routes.py index d557d02d..126b4547 100644 --- a/plugins/usb/api/routes.py +++ b/plugins/usb/api/routes.py @@ -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() diff --git a/plugins/usb/api/selfhosted.py b/plugins/usb/api/selfhosted.py index 4d8dae6a..685d3e98 100644 --- a/plugins/usb/api/selfhosted.py +++ b/plugins/usb/api/selfhosted.py @@ -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)) diff --git a/plugins/usb/migrations/versions/0004_checkin_identity.py b/plugins/usb/migrations/versions/0004_checkin_identity.py new file mode 100644 index 00000000..0e045699 --- /dev/null +++ b/plugins/usb/migrations/versions/0004_checkin_identity.py @@ -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) diff --git a/plugins/usb/models/usb_device.py b/plugins/usb/models/usb_device.py index 0b74f1dc..5a11f09f 100644 --- a/plugins/usb/models/usb_device.py +++ b/plugins/usb/models/usb_device.py @@ -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') diff --git a/tests/test_plugin_migrations.py b/tests/test_plugin_migrations.py index e2ce365f..856583e1 100644 --- a/tests/test_plugin_migrations.py +++ b/tests/test_plugin_migrations.py @@ -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' diff --git a/tests/test_plugins/test_printedparts_ledger.py b/tests/test_plugins/test_printedparts_ledger.py index 6b2ee111..0f99f876 100644 --- a/tests/test_plugins/test_printedparts_ledger.py +++ b/tests/test_plugins/test_printedparts_ledger.py @@ -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' diff --git a/tests/test_plugins/test_usb_kiosk.py b/tests/test_plugins/test_usb_kiosk.py index b4d7572c..0465b4f2 100644 --- a/tests/test_plugins/test_usb_kiosk.py +++ b/tests/test_plugins/test_usb_kiosk.py @@ -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) == []