[#343] Tamper-evident CSV audit: construct the rotatable writer once the resumed file is verified

[vharseko]

Fixes #343.

Construction order

SecureCsvWriter constructed its RotatableWriter first, and the RotatableWriter constructor schedules the rotation and retention checks. Only then did the constructor read the keys and verify the file it resumes. A check due on the resumed file, by maxFileSize or by rotationInterval from its lastModified(), could run during the construction: it renamed the file and its keystore, and postRotationAction wrote new keys into a new keystore, through the secureStorage that the verifier reads. A valid file, already archived, then failed verification, and the topic did not start.

The writer is now constructed last, once the keys are read and the file it resumes is verified. The first check runs one check interval after the construction, on a writer that holds the keys and the last signature of the file.

A file that cannot be opened

The file is still opened, and closed at once, before the keys. A file that cannot be opened, as one in a directory that cannot be created, fails with an IOException, which CsvAuditEventHandler.startup() logs for the topic. Without that, a new file would fail first when its keystore is stored, with a SecureStorageException that the constructor wraps in a RuntimeException, and the startup would fail for every topic. Opening for append leaves the file and its lastModified() as they are.

A writer whose check interval is invalid

Found in the review. The RotatableWriter constructor opened its file before it rejected an unlimited or zero rotation and retention check interval, and the caller of a constructor that throws gets no writer to close: the file stayed open until its stream was collected. An interval under one millisecond passed that check, and failed after the open with the IllegalArgumentException of scheduleAtFixedRate, which CsvAuditEventHandler.startup() does not catch for the topic. The constructor now builds the policies and checks the interval before it opens the file, and rejects an interval under one millisecond with the same IOException.

Tests

• SecureCsvWriterTest.shouldNotRotateResumedFileWhileVerifyingIt: a written file is resumed with rotation and a 50 ms check interval, with a rotation due at the first check: its size at maxFileSize, or its lastModified() two hours back with a 1 hour rotationInterval. A CommentMatcher in the CsvPreference holds the verification for 500 ms on the first line. The construction succeeds, and the first check after it rotates the file. The archive passes verification, and so does the live file, with one event after the rotation. On Windows a file that the verifier holds open cannot be renamed, and a rotation that fails to rename it still resets the time of the last rotation: there, only the rotationInterval row is sure to fail with the writer constructed first.
• SecureCsvWriterTest.shouldFailWithIOExceptionWhenFileCannotBeOpened: a file under a regular file fails with an IOException.
• SecureCsvWriterTest.shouldFailWithIOExceptionWhenCheckIntervalIsInvalidForNewFile: a new file with rotation and an unlimited check interval fails with the IOException of the RotatableWriter.
• RotatableWriterTest.testRejectsInvalidRotationRetentionCheckIntervalBeforeOpeningTheFile: an unlimited, zero or 500 microseconds check interval fails with an IOException, and the file is not created.

Measured on JDK 27:

• With the SecureCsvWriter of master, both rows fail with "The CSV file was tampered: The file contains no CSV header": with a 50 ms interval, the first check runs while the keys are read, and renames the file before the verifier opens it. With a 1 s interval and a 3 s hold, both rows fail with the reason given in the issue, "Final HMAC key doesn't match expected value".
• Without the open and close before the keys, shouldFailWithIOExceptionWhenFileCannotBeOpened fails with the RuntimeException, and so does CsvAuditEventHandlerTest.canConfigureCsvHandlerFromJsonAndRegisterWithAuditService, whose log directory /path/to/audit/files/ cannot be created.
• With the writer constructed in the try block, shouldFailWithIOExceptionWhenCheckIntervalIsInvalidForNewFile fails with "RuntimeException: Error when initializing a secure CSV writer".
• With the RotatableWriter of master, testRejectsInvalidRotationRetentionCheckIntervalBeforeOpeningTheFile fails in its three rows: the file exists for unlimited and zero, and 500 microseconds throws an IllegalArgumentException.
• audit/core and audit/handler-csv pass locally, and the new tests passed 3 runs in a row.

Merging

• With [#340] Tamper-evident CSV audit: close the file of a writer that fails to resume it #341: a conflict in the constructor. A failure in its try block now comes before the writer is constructed, so no file or rotator thread is left open (Tamper-evident CSV audit: a writer that fails to resume its file leaks it, and stops the audit service from starting #340), and the close that [#340] Tamper-evident CSV audit: close the file of a writer that fails to resume it #341 adds in the catch block would find csvWriter still null: the close goes, and the rest of [#340] Tamper-evident CSV audit: close the file of a writer that fails to resume it #341 applies as is. Its tests that the rotator thread terminates still hold, as the rotator does not start.
• With [#339] Resume a tamper-evident CSV file with no event since the last rotation #342, [#334] CSV audit: the rotate action waits for the events being written #347 and [#344] Tamper-evident CSV audit: sign the column names and the value lengths in the row HMAC #369: no conflict.

Not in this PR

• RotatableWriter schedules its checks in its constructor, and registerRotationHooks() sets the hooks after it, in a field that is not volatile. The first check runs one check interval later. Not observed; it follows from the memory model only.

[maximthomas]

praise: The change sits where the bug is, and its pin fails without it.

• constructWriter now runs at SecureCsvWriter.java:183, after the keys are read and the resumed file is verified, so the checks the RotatableWriter schedules (RotatableWriter.java:131) cannot rename the file during the construction.
• shouldNotRotateResumedFileWhileVerifyingIt fails in both rows with the SecureCsvWriter of master ("The CSV file was tampered: The file contains no CSV header", JDK 26, macOS) and passes at the head.
• The open and close at SecureCsvWriter.java:106 keeps a file that cannot be opened an IOException for its topic.

---

question (non-blocking): Should a new topic whose RotatableWriter constructor fails leave its .keystore behind?

commons/audit/handler-csv/src/main/java/org/forgerock/audit/handlers/csv/SecureCsvWriter.java:183, :163

For a new file the try block now writes InitialKey and CurrentKey into <file>.keystore (:163; KeyStoreSecureStorage.writeKey stores the keystore on each write) before constructWriter runs. With rotation enabled, maxFileSize 1000 and rotationRetentionCheckInterval "unlimited" (or "disabled"), the RotatableWriter constructor throws the same IOException as on master ("Rotation and retention check interval set to an invalid value", RotatableWriter.java:369-371), but master threw it before any key was written. The next start with a fixed config sees an empty file and overwrites both keys, so nothing is lost. If the leftover is acceptable, nothing changes; if a failed construction should leave nothing on disk, delete the keystore of a new file when constructWriter throws. Minor either way (traced, not run).

---

suggestion (non-blocking): No test pins what a failed construction of a new topic leaves on disk.

commons/audit/handler-csv/src/test/java/org/forgerock/audit/handlers/csv/SecureCsvWriterTest.java:355, SecureCsvWriter.java:183

shouldNotRotateResumedFileWhileVerifyingIt pins the order on a resumed file, and shouldFailWithIOExceptionWhenFileCannotBeOpened fails at the open (SecureCsvWriter.java:106), before any key is written; nothing covers a new file whose writer fails after :163. The case below goes red if the key writes move back after the writer (the last assertion) or if the interval stops failing the construction. Set its last assertion by the answer to the question above. Not run.

@Test
public void shouldFailWithIOExceptionWhenCheckIntervalIsInvalidForNewFile() throws Exception {
    final Path logDirectory = Files.createTempDirectory("SecureCsvWriterTest");
    final File actual =
            new File(logDirectory.toFile(), CsvAuditEventHandler.SECURE_CSV_FILENAME_PREFIX + "access.csv");
    final CsvAuditEventHandlerConfiguration config = createBasicSecureConfig("5 minutes");
    config.getFileRotation().setRotationEnabled(true);
    config.getFileRotation().setMaxFileSize(1000);
    config.setRotationRetentionCheckInterval("unlimited");
    assertThatThrownBy(() -> new SecureCsvWriter(actual, new String[]{"FOO"}, CsvPreference.EXCEL_PREFERENCE,
            config, keyStoreHandler, random))
            .isInstanceOf(IOException.class)
            .hasMessageContaining("Rotation and retention check interval set to an invalid value");
    // the head leaves the keystore of the new file; master did not create it
    assertThat(CsvSecureUtils.keyStoreFile(actual)).exists();
}

---

suggestion (non-blocking): The resumed SecureCsvWriter in shouldNotRotateResumedFileWhileVerifyingIt is closed only when the test passes.

commons/audit/handler-csv/src/test/java/org/forgerock/audit/handlers/csv/SecureCsvWriterTest.java:322-333

The writer built at :322 is closed at :333, outside any try, while the first writer of the same test (:290) is in try-with-resources. If the assertion at :324, the wait or writeEvent fails, its RotatableWriter rotator (Executors.newScheduledThreadPool(1), non-daemon, RotatableWriter.java:373) goes on checking every 50 ms for the rest of the surefire JVM, and on Windows the file stays open. fileNamingPolicy moves before the writer, as the verification after the block reads it.

        final FileNamingPolicy fileNamingPolicy = new TimeStampFileNamingPolicy(actual, rotationFileSuffix, "");
        try (SecureCsvWriter secureCsvWriter = new SecureCsvWriter(
                actual, new String[]{header}, slowToVerify, config, keyStoreHandler, random)) {
            assertThat(held.get()).as("verification held").isTrue();

            // the first check after the construction rotates the file
            final long deadline = System.nanoTime() + TimeUnit.SECONDS.toNanos(10);
            while (fileNamingPolicy.listFiles().isEmpty() && System.nanoTime() < deadline) {
                Thread.sleep(10);
            }
            secureCsvWriter.writeEvent(singletonMap(header, "after"));
        }

---

suggestion (non-blocking): On Windows, only the rotationInterval row is sure to catch a reverted order.

commons/audit/handler-csv/src/test/java/org/forgerock/audit/handlers/csv/SecureCsvWriterTest.java:273-281, :301

With the SecureCsvWriter of master on Windows, a check during the 500 ms hold cannot rename the file the verifier holds open (FileInputStream does not share delete), and RotatableWriter.rotate still resets lastRotationTime. The rotationInterval row then rotates no more within the hour and fails hasSize(1). The maxFileSize row stays over its size and rotates at the next check after verify() closed its reader, usually once the constructor has returned, so it fails only when a check renames the file before the verifier opens it. Traced, not run on Windows. A line in the data provider's comment saying which row pins the order on Windows keeps that from being lost.

[vharseko]

Round 1 is in 7ede4f2, on a branch rebased onto the current master.

Question: the .keystore that a new topic leaves when its writer fails. Left as is. master did not leave the disk clean either: the RotatableWriter constructor opened the file (RotatableWriter.java:128) before it threw for the interval (:370), so the empty .csv stays on both; the head adds its keystore. The next start with a fixed interval reads the empty file as a new one and overwrites both keys: run against both, the file written at that start passes verification. A cleanup there would add a file delete to a configuration error path, with no effect on the next start.

Suggestion: a test for a new file whose writer fails. Added as shouldFailWithIOExceptionWhenCheckIntervalIsInvalidForNewFile, without the last assertion: the keystore it leaves is not a contract, and a reverted order is pinned by shouldNotRotateResumedFileWhileVerifyingIt. What the test pins is the IOException: with the writer constructed in the try block, it fails with "RuntimeException: Error when initializing a secure CSV writer", which CsvAuditEventHandler.startup() does not catch for the topic.

Suggestion: the resumed writer is closed only when the test passes. Done as proposed.

Suggestion: on Windows, only the rotationInterval row is sure to catch a reverted order. The data provider says so now, and that the maxFileSize row fails there when a check renames the file before the verifier opens it.

Found while tracing the question. The RotatableWriter constructor opened its file before it rejected the interval, and the caller of a constructor that throws gets no writer to close, so the case of the new test left the file open. An interval under one millisecond passed that check, and failed after the open with the IllegalArgumentException of scheduleAtFixedRate. The constructor now checks the interval before it opens the file, and rejects an interval under one millisecond with the same IOException: RotatableWriterTest.testRejectsInvalidRotationRetentionCheckIntervalBeforeOpeningTheFile, which fails in its three rows with the RotatableWriter of master. The description has a section on it.