From c2fde973a57cf435d84b9d5c6f6d3aa490cf74dc Mon Sep 17 00:00:00 2001 From: James Maes Date: Sat, 14 Nov 2026 03:39:54 -0600 Subject: [PATCH] fix: a reveal and the access-log writer no longer wait for each other A reveal, and the start, end and expiry of a break-glass session, hold the runtime's monitor from their first check to their last write. Asking for a classification (SecuredDataRuntime.classificationRows, and activeRetentionRules) took the same monitor, and every thread asks: core asks for every field it decides on and for every filter criterion of every query, including the queries made inside this QBit's own writes. So a thread that asked while holding another lock of this QBit could not be answered during a reveal, and if the reveal needed that lock next, both waited for ever. The access-log writer is such a thread. It holds the anomaly counters while it inserts a row; the insert counts earlier rows and writes an audit, both queries with criteria. A reveal inserts its own access-log row. reveal: runtime's monitor, then the anomaly counters writer: the anomaly counters, then the runtime's monitor Seen in a host on PostgreSQL: a person read a record with a masked field and revealed it at once; the writer's tick drained the read's log rows at the same moment. The request and the writer deadlocked (thread dump: the request in SystemWrites.insertOne under RevealService.reveal, the writer in SecuredDataRuntime.classificationRows under AuditAction.fetchIdFromName under its own insert), and every later request blocked in classificationRows. The same order existed between a reveal and the resolver's monitor, and the key source's. - The rule rows have a lock of their own (ruleLock), held only while they are answered or read. A read is a query made as the system and takes none of the QBit's other locks, so nothing that holds ruleLock waits for one. - The runtime's monitor is left to what it was for: one reveal or break-glass change at a time. Tests (SecuredDataLockOrderTest, on H2 in PostgreSQL mode with the audit tables): a thread is parked inside a reveal, and inside the start of a break-glass session, holding the runtime's monitor; the access-log writer must drain its queue and another thread must be told a classification and the active retention rules meanwhile, and then the parked operation must finish. Both tests fail without the fix (neither thread finishes). Co-Authored-By: Claude Fable 5.2 --- CHANGELOG.md | 4 + .../kingsrook/qbits/secureddata/RuleRows.java | 11 +- .../qbits/secureddata/SecuredDataRuntime.java | 36 ++- .../secureddata/SecuredDataLockOrderTest.java | 271 ++++++++++++++++++ .../secureddata/SecuredDataTestSupport.java | 9 + 5 files changed, 318 insertions(+), 13 deletions(-) create mode 100644 src/test/java/com/kingsrook/qbits/secureddata/SecuredDataLockOrderTest.java diff --git a/CHANGELOG.md b/CHANGELOG.md index af02794..927316c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,10 @@ All notable changes are documented here, following [Keep a Changelog](https://ke ## [Unreleased] +### Fixed: a reveal and the access-log writer waiting for each other +- A reveal, or the start, end or expiry of a break-glass session, no longer deadlocks with a thread that asks for a classification while it holds another lock of this QBit. The access-log writer is such a thread: it holds the anomaly counters while it inserts a row, and that insert asks for classifications (it counts earlier rows and writes an audit, both queries with criteria). A reveal holds the runtime's monitor and then inserts its own access-log row. When both happened at once, neither finished, and neither did any later request, because every request asks for a classification. A person who opens a record with a masked field and reveals it straight away does both at once. +- The rule rows a node keeps (classifications, active retention rules) have a lock of their own, held only while they are answered or read. Asking for a classification no longer takes the monitor that reveal and break-glass hold for their whole operation. + ### Fixed: rule reads that ask for their own rows - Reading the rule rows a node keeps (classifications, active retention rules, policies) no longer recurses when code that runs inside that read asks for the same rows. Another QBit's virtual field value provider, or a post-query customizer, on a secured-data table that ran a query with filter criteria did exactly that: with one classification row present, every request that needed a classification ended in a `StackOverflowError`. - The QBit's system reads of its own tables (`SystemWrites.query`, the audit key lookup) name the stored fields of the table, so core runs no virtual field value provider inside them. diff --git a/src/main/java/com/kingsrook/qbits/secureddata/RuleRows.java b/src/main/java/com/kingsrook/qbits/secureddata/RuleRows.java index d9f25ed..79dd83f 100644 --- a/src/main/java/com/kingsrook/qbits/secureddata/RuleRows.java +++ b/src/main/java/com/kingsrook/qbits/secureddata/RuleRows.java @@ -32,11 +32,12 @@ import com.kingsrook.qqq.backend.core.model.data.QRecord; ** SecuredDataRuntime.MAX_RULE_AGE, and safe against a read that asks for the ** same rows again. ** - ** Not synchronized: every call must be made holding the owner's monitor (the - ** runtime for classifications and retention rules, the resolver for policies). - ** That monitor is what makes the re-entry answer below private to one thread: - ** while a read is running, only the thread running it can get in here; every - ** other thread waits for the monitor and is given the rows that read returns. + ** Not synchronized: every call must be made holding the owner's lock (the + ** runtime's rule lock for classifications and retention rules, the resolver's + ** monitor for policies). That lock is what makes the re-entry answer below + ** private to one thread: while a read is running, only the thread running it + ** can get in here; every other thread waits for the lock and is given the rows + ** that read returns. ** ** Re-entry: reading rule rows is itself a query, and anything that runs inside ** it (a table customizer, a record-security lookup, a value provider) may ask a diff --git a/src/main/java/com/kingsrook/qbits/secureddata/SecuredDataRuntime.java b/src/main/java/com/kingsrook/qbits/secureddata/SecuredDataRuntime.java index 7e2ead8..2b4ceba 100644 --- a/src/main/java/com/kingsrook/qbits/secureddata/SecuredDataRuntime.java +++ b/src/main/java/com/kingsrook/qbits/secureddata/SecuredDataRuntime.java @@ -79,10 +79,24 @@ public class SecuredDataRuntime implements QSupplementalInstanceMetaData, AutoCl private final transient SecuredDataAccessLogger logger; private final transient SecuredDataAnomalies anomalies; ///////////////////////////////////////////////////////////////////////////////// - // both are used only inside methods synchronized on this runtime: one monitor // - // for the two, because reading either may ask for the other // + // both are used only while holding ruleLock: one lock for the two, because // + // reading either may ask for the other. // + // // + // It is a lock of its own, never this runtime's monitor. A reveal and the // + // start, end and expiry of a break-glass session hold the runtime's monitor // + // for their whole operation, and every thread asks for a classification all // + // the time (core asks for every field it decides on and for every criterion // + // of every query), including threads that hold another lock of this QBit: the // + // access-log writer inside the anomaly counters, the resolver, the key // + // source. When the question needed the runtime's monitor, such a thread and // + // a reveal that needed its lock next waited for each other for ever. // + // // + // ruleLock is held only while rule rows are answered or read. A read is a // + // query made as the system: it takes none of the QBit's other locks, so no // + // thread holding ruleLock ever waits for one of them. // ///////////////////////////////////////////////////////////////////////////////// - private final transient RuleRows classificationRows = new RuleRows(); + private final transient Object ruleLock = new Object(); + private final transient RuleRows classificationRows = new RuleRows(); private final transient RuleRows activeRetentionRules = new RuleRows(); @@ -232,10 +246,13 @@ public class SecuredDataRuntime implements QSupplementalInstanceMetaData, AutoCl ** next call reads again. A question asked from inside the read itself (see ** RuleRows) is answered with the rules held when the read began. *******************************************************************************/ - public synchronized List activeRetentionRules() + public List activeRetentionRules() { - return (activeRetentionRules.get(retentionVersion(), () -> SystemWrites.query(SecuredDataTables.RETENTION_RULE, new QQueryFilter() - .withCriteria(new QFilterCriteria("is_active", QCriteriaOperator.EQUALS, true))))); + synchronized(ruleLock) + { + return (activeRetentionRules.get(retentionVersion(), () -> SystemWrites.query(SecuredDataTables.RETENTION_RULE, new QQueryFilter() + .withCriteria(new QFilterCriteria("is_active", QCriteriaOperator.EQUALS, true))))); + } } @@ -289,9 +306,12 @@ public class SecuredDataRuntime implements QSupplementalInstanceMetaData, AutoCl ** inside the read itself (see RuleRows) is answered with the rows held when ** the read began, and never starts another read. *******************************************************************************/ - synchronized List classificationRows() + List classificationRows() { - return (classificationRows.get(classificationVersion(), () -> SystemWrites.query(SecuredDataTables.CLASSIFICATION, new QQueryFilter()))); + synchronized(ruleLock) + { + return (classificationRows.get(classificationVersion(), () -> SystemWrites.query(SecuredDataTables.CLASSIFICATION, new QQueryFilter()))); + } } diff --git a/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataLockOrderTest.java b/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataLockOrderTest.java new file mode 100644 index 0000000..8d295ce --- /dev/null +++ b/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataLockOrderTest.java @@ -0,0 +1,271 @@ +/* + * QQQ - Low-code Application Framework for Engineers. + * Copyright (C) 2021-2025. Kingsrook, LLC + * 651 N Broad St Ste 205 # 6917 | Middletown DE 19709 | United States + * contact@kingsrook.com + * https://github.com/Kingsrook/ + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.kingsrook.qbits.secureddata; + + +import java.io.Serializable; +import java.util.List; +import java.util.concurrent.Callable; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicReference; +import com.kingsrook.qbits.secureddata.breakglass.BreakGlassService; +import com.kingsrook.qbits.secureddata.metadata.SecuredDataTables; +import com.kingsrook.qbits.secureddata.reveal.RevealResult; +import com.kingsrook.qbits.secureddata.reveal.RevealService; +import com.kingsrook.qqq.backend.core.actions.ai.DataClassification; +import com.kingsrook.qqq.backend.core.actions.permissions.fieldaccess.FieldAccessEvent; +import com.kingsrook.qqq.backend.core.actions.permissions.fieldaccess.FieldAccessEventType; +import com.kingsrook.qqq.backend.core.actions.permissions.fieldaccess.FieldAccessOutcome; +import com.kingsrook.qqq.backend.core.context.QContext; +import com.kingsrook.qqq.backend.core.model.data.QRecord; +import com.kingsrook.qqq.backend.core.model.metadata.QInstance; +import com.kingsrook.qqq.backend.core.model.metadata.tables.QTableMetaData; +import com.kingsrook.qqq.backend.core.model.session.QSession; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.Timeout; +import static com.kingsrook.qbits.secureddata.SecuredDataTestSupport.CLOCK; +import static com.kingsrook.qbits.secureddata.SecuredDataTestSupport.insert; +import static com.kingsrook.qbits.secureddata.SecuredDataTestSupport.logs; +import static com.kingsrook.qbits.secureddata.SecuredDataTestSupport.policyRow; +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.fail; + + +/******************************************************************************* + ** A reveal, and the start, end and expiry of a break-glass session, hold the + ** runtime's monitor from their first check to their last write, so that two of + ** them cannot both pass a check (the daily allowance, one active session). + ** Every other thread asks this QBit for a classification all the time: core + ** asks for every field it decides on and for every filter criterion of every + ** query, including the queries made inside this QBit's own writes. + ** + ** When that question needed the same monitor, a thread that asked it while + ** holding another of this QBit's locks could never be answered during a + ** reveal that was about to need that lock: the access-log writer holds the + ** anomaly counters' monitor while it inserts a row (the insert counts earlier + ** rows and writes an audit, both queries with criteria), and a reveal inserts + ** its own access-log row. Reveal: runtime, then counters. Writer: counters, + ** then runtime. Both waited for ever, and so did every later request, since + ** every request asks for a classification. + ** + ** The rule rows now have a lock of their own that is held only while they are + ** read. These tests run on a relational database (H2 in PostgreSQL mode, with + ** the audit tables), where an insert really writes its audit. Each parks one + ** thread inside the operation, holding the runtime's monitor, and requires + ** the access-log writer and a classification question on other threads to + ** finish meanwhile; then the parked operation finishes too. Without the fix + ** the writer does not finish and the test fails after WAIT_SECONDS. + *******************************************************************************/ +@Timeout(180) +class SecuredDataLockOrderTest +{ + private static final long WAIT_SECONDS = 20; + + private final ExecutorService threads = Executors.newCachedThreadPool(work -> + { + Thread thread = new Thread(work, "lock-order-test"); + thread.setDaemon(true); + return (thread); + }); + + private QInstance instance; + private SecuredDataRuntime runtime; + private QSession person; + private QTableMetaData reading; + private Serializable pk; + + private final CountDownLatch parked = new CountDownLatch(1); + private final CountDownLatch resume = new CountDownLatch(1); + private final AtomicReference working = new AtomicReference<>(); + private final AtomicBoolean heldTheRuntimesMonitor = new AtomicBoolean(); + + + + /******************************************************************************* + ** Let a parked thread go, then close; a runtime whose threads are stuck was + ** already taken out of the list (see abandon). + *******************************************************************************/ + @AfterEach + void cleanup() + { + resume.countDown(); + threads.shutdownNow(); + RetentionTestSupport.close(); + } + + + + /******************************************************************************* + ** A reveal in progress holds up neither the access-log writer nor a question. + *******************************************************************************/ + @Test + void theAccessLogWriterAndAClassificationQuestionFinishWhileARevealIsInProgress() throws Exception + { + setup(); + Future reveal = parkInside(() -> new RevealService().reveal("reading", pk, "notes", null, "Synthetic reveal; lock order test.")); + + othersFinishMeanwhile(); + + resume.countDown(); + assertThat(reveal.get(WAIT_SECONDS, TimeUnit.SECONDS).value()).isEqualTo("test-notes"); + assertThat(logs()).extracting(row -> row.getValueString("event_type")).contains("EXACT_MATCH_FILTER", "REVEAL"); + assertThat(runtime.resolver().isRevealActive("reading", "notes", pk)).isTrue(); + } + + + + /******************************************************************************* + ** The same for the start of a break-glass session, which holds the same monitor. + *******************************************************************************/ + @Test + void theAccessLogWriterAndAClassificationQuestionFinishWhileBreakGlassStarts() throws Exception + { + setup(); + person.getPermissions().add(BreakGlassService.START + ".hasAccess"); + Future started = parkInside(() -> new BreakGlassService().start("Synthetic break-glass session; lock order test.", 5, "reading", DataClassification.PHI)); + + othersFinishMeanwhile(); + + resume.countDown(); + assertThat(started.get(WAIT_SECONDS, TimeUnit.SECONDS).getValueString("status")).isEqualTo("ACTIVE"); + assertThat(logs()).extracting(row -> row.getValueString("event_type")).contains("EXACT_MATCH_FILTER", "BREAK_GLASS_START"); + } + + + + /******************************************************************************* + ** A relational instance with audit tables; a PII field one policy makes + ** revealable to the person; one row; and one search of that field waiting in + ** the access-log queue, as it waits after a person filters a list by it. + *******************************************************************************/ + private void setup() throws Exception + { + instance = RetentionTestSupport.setup(); + runtime = SecuredDataRuntime.current(); + person = QContext.getQSession(); + reading = instance.getTable("reading"); + insert(SecuredDataTables.POLICY, policyRow("secured_data.admin", "PII", "REVEALABLE")); + pk = RetentionTestSupport.reading(120).getValue("id"); + + runtime.resolver().onAccess(new FieldAccessEvent().withType(FieldAccessEventType.EXACT_MATCH_FILTER).withOutcome(FieldAccessOutcome.MATCH) + .withTableName("reading").withFieldNames(List.of("notes")).withActionName("query").withRecordCount(1) + .withSearchValueFingerprints(List.of(runtime.resolver().fingerprintSearchValue("known")))); + assertThat(logs()).as("the search is queued, not yet written").extracting(row -> row.getValueString("event_type")).doesNotContain("EXACT_MATCH_FILTER"); + } + + + + /******************************************************************************* + ** Run the operation as the person on another thread and return once it is + ** parked at its first reading of the clock, which both operations make + ** inside their synchronized block. + *******************************************************************************/ + private Future parkInside(Callable operation) throws Exception + { + CLOCK.beforeInstant = () -> + { + if(Thread.currentThread() == working.get() && parked.getCount() == 1) + { + heldTheRuntimesMonitor.set(Thread.holdsLock(runtime)); + parked.countDown(); + try + { + resume.await(); + } + catch(InterruptedException e) + { + Thread.currentThread().interrupt(); + } + } + }; + Future future = threads.submit(() -> + { + QContext.init(instance, person); + try + { + working.set(Thread.currentThread()); + return (operation.call()); + } + finally + { + QContext.clear(); + } + }); + assertThat(parked.await(WAIT_SECONDS, TimeUnit.SECONDS)).as("the operation read the clock").isTrue(); + assertThat(heldTheRuntimesMonitor).as("the operation is parked holding the runtime's monitor").isTrue(); + return (future); + } + + + + /******************************************************************************* + ** While the operation is parked: the access-log writer drains its queue (what + ** its worker does on every tick), and a thread that holds no lock is told + ** the classification of a field and the active retention rules. + *******************************************************************************/ + private void othersFinishMeanwhile() throws Exception + { + Future writer = threads.submit(() -> runtime.logger().flush()); + Future question = threads.submit(() -> + { + QContext.init(instance, person); + try + { + runtime.activeRetentionRules(); + return (SecuredDataClassifications.effective(reading, "notes")); + } + finally + { + QContext.clear(); + } + }); + + try + { + writer.get(WAIT_SECONDS, TimeUnit.SECONDS); + assertThat(question.get(WAIT_SECONDS, TimeUnit.SECONDS)).isEqualTo(DataClassification.PII); + } + catch(TimeoutException e) + { + abandon(); + fail("A thread waited " + WAIT_SECONDS + " seconds for the monitor the parked operation holds (writer done: " + writer.isDone() + ", question done: " + question.isDone() + + "): the operation needs the lock that thread holds next, so neither would ever finish"); + } + } + + + + /******************************************************************************* + ** Threads of this runtime are stuck holding its locks: closing it would wait + ** for them, so it is left to the daemon threads instead of being closed. + *******************************************************************************/ + private void abandon() + { + SecuredDataTestSupport.RUNTIMES.remove(runtime); + } +} diff --git a/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataTestSupport.java b/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataTestSupport.java index 3d87045..ab51afc 100644 --- a/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataTestSupport.java +++ b/src/test/java/com/kingsrook/qbits/secureddata/SecuredDataTestSupport.java @@ -234,6 +234,7 @@ final class SecuredDataTestSupport *******************************************************************************/ static void close() { + CLOCK.beforeInstant = null; RUNTIMES.forEach(SecuredDataRuntime::close); RUNTIMES.clear(); QContext.clear(); @@ -248,6 +249,9 @@ final class SecuredDataTestSupport { Instant now = NOW; + /** Run on the reading thread before every reading of the clock; a test parks a thread at a known point with it. */ + volatile Runnable beforeInstant; + /******************************************************************************* @@ -275,6 +279,11 @@ final class SecuredDataTestSupport *******************************************************************************/ public Instant instant() { + Runnable hook = beforeInstant; + if(hook != null) + { + hook.run(); + } return (now); } } -- 2.54.0