[CASSANDRA-17933] Zero length file in Audit log folder, prevents a node from starting

• Type: Bug
• Status: Resolved
• Priority: Normal
• Resolution: Fixed
• Fix Version/s: 4.0.7, 4.1-rc1, 4.1, 5.0-alpha1, 5.0
• Component/s: Local/Startup and Shutdown
• Bug Category: Availability - Process Crash
• Severity: Normal
• Complexity: Normal
• Discovered By: User Report
• Platform: All
• Since Version: 4.0.0

Source Control Link

https://github.com/apache/cassandra/commit/488c0c75a8f632f2db4e3db39f2ebcf8a489971e

Test and Documentation Plan

junits + dtest

• Assignee: Stefan Miklosovic
• Reporter: Andrew Hogg

Authors

Stefan Miklosovic

Reviewers

Caleb Rackliffe

• Created: 29/Sep/22 08:17
• Updated: 12/Sep/23 13:02
• Resolved: 11/Oct/22 21:37

Description

We have encountered a 4.0.3 cluster where the audit log folder had a zero byte length file within it after the node had stopped. It is not clear how Cassandra got to the point of this file existing. On restarting the node, the node will not start and throws the following stack trace.

ERROR [main] 2022-09-26 14:01:27,892 CassandraDaemon.java:911 - Exception encountered during startup
java.lang.ExceptionInInitializerError: null
        at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:468)
        at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:765)
        at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:889)
Caused by: org.apache.cassandra.exceptions.ConfigurationException: Unable to create instance of IAuditLogger.
        at org.apache.cassandra.utils.FBUtilities.newAuditLogger(FBUtilities.java:686)
        at org.apache.cassandra.audit.AuditLogManager.getAuditLogger(AuditLogManager.java:95)
        at org.apache.cassandra.audit.AuditLogManager.<init>(AuditLogManager.java:74)
        at org.apache.cassandra.audit.AuditLogManager.<clinit>(AuditLogManager.java:60)
        ... 3 common frames omitted
Caused by: java.lang.reflect.InvocationTargetException: null
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at org.apache.cassandra.utils.FBUtilities.newAuditLogger(FBUtilities.java:682)
        ... 6 common frames omitted
Caused by: java.nio.channels.OverlappingFileLockException: null
        at sun.nio.ch.SharedFileLockTable.checkList(FileLockTable.java:255)
        at sun.nio.ch.SharedFileLockTable.add(FileLockTable.java:152)
        at sun.nio.ch.FileChannelImpl.lock(FileChannelImpl.java:1068)
        at java.nio.channels.FileChannel.lock(FileChannel.java:1053)
        at net.openhft.chronicle.bytes.MappedFile.resizeRafIfTooSmall(MappedFile.java:369)
        at net.openhft.chronicle.bytes.MappedFile.acquireByteStore(MappedFile.java:307)
        at net.openhft.chronicle.bytes.MappedFile.acquireByteStore(MappedFile.java:269)
        at net.openhft.chronicle.bytes.MappedBytes.acquireNextByteStore0(MappedBytes.java:434)
        at net.openhft.chronicle.bytes.MappedBytes.readVolatileInt(MappedBytes.java:792)
        at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue$StoreSupplier.headerRecovery(SingleChronicleQueue.java:1027)
        at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue$StoreSupplier.acquire(SingleChronicleQueue.java:981)
        at net.openhft.chronicle.queue.impl.WireStorePool.acquire(WireStorePool.java:53)
        at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.cleanupStoreFilesWithNoData(SingleChronicleQueue.java:821)
        at net.openhft.chronicle.queue.impl.single.StoreAppender.<init>(StoreAppender.java:75)
        at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.newAppender(SingleChronicleQueue.java:422)
        at net.openhft.chronicle.core.threads.CleaningThreadLocal.initialValue(CleaningThreadLocal.java:54)
        at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:180)
        at java.lang.ThreadLocal.get(ThreadLocal.java:170)
        at net.openhft.chronicle.core.threads.CleaningThreadLocal.get(CleaningThreadLocal.java:59)
        at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.acquireAppender(SingleChronicleQueue.java:441)
        at org.apache.cassandra.utils.binlog.BinLog.<init>(BinLog.java:133)
        at org.apache.cassandra.utils.binlog.BinLog.<init>(BinLog.java:65)
        at org.apache.cassandra.utils.binlog.BinLog$Builder.build(BinLog.java:453)
        at org.apache.cassandra.audit.BinAuditLogger.<init>(BinAuditLogger.java:55)
        ... 11 common frames omitted 

To reproduce, we place a zero length file and attempted to start the node, and saw the same stack trace.

ll ../logs/audit/
total 4
rw-rw-r-. 1 automaton automaton 0 Sep 28 13:00 20220928-12.cq4
rw-rw-r-. 1 automaton automaton 131072 Sep 28 13:00 metadata.cq4t