Aof unable to recover?

[arnabp]

My Garnet server recently become unable to recover from last checkpoint. Notably, it used to recover the HybridLog Stats fine, and then initiate the AOF replay, but, despite no changes to the config, it did this on the last server reset:

2024-11-09 06:42:49 10::42::49 info: TsavoriteKV [main][0] ********* Primary Recovery Information ********
2024-11-09 06:42:49 10::42::49 info: StoreWrapper[0] Error during recovery of store; storeVersion = -1; objectStoreVersion = -1 Tsavorite.core.TsavoriteException: Unable to find valid HybridLog token    at Tsavorite.core.TsavoriteKV`4.FindRecoveryInfo(Int64 requestedVersion, HybridLogCheckpointInfo& recoveredHlcInfo, IndexCheckpointInfo& recoveredICInfo) in /src/libs/storage/Tsavorite/cs/src/core/Index/Recovery/Recovery.cs:line 327    at Tsavorite.core.TsavoriteKV`4.Recover(Int32 numPagesToPreload, Boolean undoNextVersion, Int64 recoverTo) in /src/libs/storage/Tsavorite/cs/src/core/Index/Tsavorite/Tsavorite.cs:line 349    at Garnet.server.StoreWrapper.RecoverCheckpoint(Boolean recoverMainStoreFromToken, Boolean recoverObjectStoreFromToken, Guid storeIndexToken, Guid storeHlogToken, Guid objectStoreIndexToken, Guid objectStoreHlogToken) in /src/libs/server/StoreWrapper.cs:line 245
2024-11-09 06:42:49 10::42::49 info: TsavoriteLog [aof][0] Unable to recover using any available commit
2024-11-09 06:42:49 10::42::49 info: StoreWrapper[0] Recovered AOF: begin address = 64, tail address = 64
2024-11-09 06:42:49 10::42::49 dbug: Session[0] [] [0139BFB8] Starting RespServerSession Id=0
2024-11-09 06:42:49 10::42::49 info: StoreWrapper[0] Begin AOF recovery
2024-11-09 06:42:49 10::42::49 info: StoreWrapper[0] Begin AOF replay
2024-11-09 06:42:49 10::42::49 info: StoreWrapper[0] Completed full AOF log replay of 0 record

It's worth pointing out that I'm using a configuration that involves a primary garnet server along with a secondary that functions as a low compute/memory backup who's purpose is only to write to aof in case of the primary being down. My guess is that maybe this strategy failed and somehow corrupted the checkpoint but I did test this in development and the primary was able to pickup the data that the secondary wrote while the primary was down so I hadn't expected this kind of failure, but given what I'm doing I'm not sure if this is a bug or a bad config based on a misunderstanding of how AOF works. Here are my config files:

docker-compose.yml

services:
  garnet_primary:
    image: 'ghcr.io/microsoft/garnet'
    ulimits:
      memlock: -1
      core: -1
    ports:
      - "6379:6379"
    command: ["--config-import-path", "garnet.conf"]
    volumes:
      - garnetdata:/data
      - ./garnet.conf:/app/garnet.conf
      - ./core_dumps:/core_dumps
    environment:
      - CORE_DUMP_DEST=/core_dumps
    cap_add:
      - SYS_PTRACE
    restart: always

  garnet_secondary:
    image: 'ghcr.io/microsoft/garnet'
    ulimits:
      memlock: -1
    ports:
      - "6380:6380"
    command: ["--config-import-path", "garnet.conf"]
    volumes:
      - garnetdata:/data
      - ./garnet-aof.conf:/app/garnet.conf
    restart: always

networks:
  my_network:
    external: true
volumes:
  garnetdata:

garnet.conf

{
  "Port": 6379,
  "MemorySize": "32g",
  "IndexResizeThreshold": 80,
  "IndexResizeFrequencySecs" : 86400,
  "EnableStorageTier": true,
  "LogDir": "/data/log",
  "CheckpointDir": "/data/checkpoint",
  "Recover": true,
  "CompactionType": "scan",
  "UseNativeDeviceLinux": true,
  "EnableAOF": true,
  "LogLevel": "Debug"
}

garnet-aof.conf

{
  "Port": 6380,
  "MemorySize": "64mb",
  "CheckpointDir": "/data/checkpoint",
  "Recover": false,
  "CompactionFrequencySecs": "0",
  "UseNativeDeviceLinux": true,
  "EnableAOF": true,
  "AofMemorySize": "2m",
  "AofPageSize": "1m",
  "LogLevel": "Debug"
}

[arnabp]

After a lot of debugging I have narrowed it down to the following:

First, the step that is causing Garnet to be unable to recover at all is the FastCommit mode being enable, which is calling ScanForwardForCommit. It's not clear to me why ScanForwardForCommit is unable to find any available commit, why FastCommit mode has this behavior, or even what FastCommit mode does (I have not seen any information about it in the documentation), but setting FastCommit mode to false causes Garnet to at least be able to start reading commits and replaying records.

Second, unfortunately I'm still having an issue because somewhere along my commit history there appears to be some sort of data corruption that causes the replaying of records to break. Specifically, at a certain record (Record A) it jumps way ahead in the commit data and lands on the wrong part of another record (Record B). Record A ends with a length byte of 0 so it triggers the logic that skips to the next page when it encounters trailing zeroed out bytes. And indeed Record A does have trailing zeroed out bytes but it is not close to the end of the page. Unlike other instances where we skip to the next page, which results in byte jumps between 4 and ~350 bytes, this jump skips ahead 3496116 bytes to get to Record B. Record B doesn't doesn't start with the typical 0x01 which is the aofHeaderVersion of all the other records, but instead with 0x11 which is the opType of the other records, ObjectStoreRMW. Garnet doesn't seem to register that the aofHeaderVersion is different, but it instead picks up what I assume is supposed to be the StoreVersion 0x01 as the opType and tries to read this record as a StoreRMW. I don't really know what the difference is between ObjectStoreRMW and StoreRMW but given that this is the first time in the checkpoint data that it's encountered I'm assuming it's a mistake. So my best guess is that the jump from Record A to Record B lands two bytes ahead of where it's supposed to causing Record B to be read wrong and causing the AOF replay to fail.

I've tried deleting the trailing zeroed out bytes from Record A and I've tried removing the aof.log file that contained these records entirely but neither of these worked, I assume because the AOF replay isn't designed for that. I've pretty much reached the limit of my knowledge of how this system works and how much I can get away with figuring out by stepping through the debugger. If there's a way to fix the corrupted data that would be ideal but if I can even just skip over the corrupted data that would work too, the AOF replay is halting on log file 3 out of 88 so I'd really like to be able to recover the vast majority of the data.