snapshot successfully sent to S3, but not WAL segments

[laser]

Hi, folks. Thanks for the cool product. We use it here at the office and love it.

Recently we ran into an issue in which Litestream is capable of creating snapshots and persisting them to an S3 bucket, but does not appear to be performing the once-per-second sync.

This can be reproduced trivially on our Ubuntu 22.04.3 LTS host with Litestream 0.3.9 and SQLite3 3.37.2.

Example Litestream configuration YAML:

access-key-id:     ${AWS_ACCESS_KEY_ID}
secret-access-key: ${AWS_SECRET_ACCESS_KEY}

dbs:
  - path: /home/motherbrain/example.db
    replicas:
      - type: s3
        bucket: ${AWS_S3_BUCKET_NAME}
        path:   ${AWS_S3_PATH}
        region: ${AWS_REGION}

Example database creation and pragma-setting:

motherbrain@cnc-motherbrain-01:~$ touch /home/motherbrain/example.db

motherbrain@cnc-motherbrain-01:~$ sqlite3 /home/motherbrain/example.db "PRAGMA synchronous = NORMAL;"

motherbrain@cnc-motherbrain-01:~$ sqlite3 /home/motherbrain/example.db "PRAGMA journal_mode=WAL;"
-- Loading resources from /home/motherbrain/.sqliterc
journal_mode
------------
wal

Creating some tables:

echo -e "CREATE TABLE fruits (name TEXT, color TEXT);\nINSERT INTO fruits (name, color) VALUES ('apple', 'red');\nINSERT INTO fruits (name, color) VALUES ('banana', 'yellow');" | sqlite3 /home/motherbrain/example.db

motherbrain@cnc-motherbrain-01:~$ sqlite3 /home/motherbrain/example.db "SELECT * FROM fruits;"
-- Loading resources from /home/motherbrain/.sqliterc
name    color
------  ------
apple   red
banana  yellow

Starting Litestream:

motherbrain@cnc-motherbrain-01:~$ env $(cat /home/motherbrain/.env.litestream | xargs) /usr/bin/litestream replicate --config /etc/cnc-cell/litestream.yml
litestream v0.3.9
initialized db: /home/motherbrain/example.db
replicating to: name="s3" type="s3" bucket="XXX" path="YYY" region="ZZZ" endpoint="" sync-interval=1s
/home/motherbrain/example.db: sync: new generation "c1f20049ce3453eb", no generation exists
/home/motherbrain/example.db(s3): snapshot written c1f20049ce3453eb/00000000

Then, in a separate shell:

motherbrain@cnc-motherbrain-01:~$ echo -e "INSERT INTO fruits (name, color) VALUES (RANDOM(), 'yellow');" | sqlite3 /home/motherbrain/example.db
motherbrain@cnc-motherbrain-01:~$ echo -e "INSERT INTO fruits (name, color) VALUES (RANDOM(), 'yellow');" | sqlite3 /home/motherbrain/example.db
motherbrain@cnc-motherbrain-01:~$ echo -e "INSERT INTO fruits (name, color) VALUES (RANDOM(), 'yellow');" | sqlite3 /home/motherbrain/example.db

motherbrain@cnc-motherbrain-01:~$ sqlite3 /home/motherbrain/example.db "SELECT * FROM fruits;"
-- Loading resources from /home/motherbrain/.sqliterc
name                  color
--------------------  ------
apple                 red
banana                yellow
8480735284958646460   yellow
-5945044387730647060  yellow
-4852700256047190186  yellow

In the shell running Litestream, I see no "write wal segment" or "wal segment written" output.

Finally, when I list generations for my database, the lag displays as a negative value:

motherbrain@cnc-motherbrain-01:~$ env $(cat /home/motherbrain/.env.litestream | xargs) /usr/bin/litestream generations --config /etc/cnc-cell/litestream.yml /home/motherbrain/example.db
name  generation        lag     start                 end
s3    c1f20049ce3453eb  -227ms  2023-12-14T17:03:52Z  2023-12-14T17:04:52Z

I have verified that new artifacts are making their way to S3, though:

09:08 $ aws s3 ls s3://hadrian-itar-production/program/motherbrain --recursive
2023-12-14 09:03:52        409 program/motherbrain/generations/c1f20049ce3453eb/snapshots/00000000.snapshot.lz4
2023-12-14 09:03:52        476 program/motherbrain/generations/c1f20049ce3453eb/wal/00000000_00000000.wal.lz4
2023-12-14 09:04:11        141 program/motherbrain/generations/c1f20049ce3453eb/wal/00000000_00004080.wal.lz4
2023-12-14 09:04:12        166 program/motherbrain/generations/c1f20049ce3453eb/wal/00000000_00005098.wal.lz4
2023-12-14 09:04:13        198 program/motherbrain/generations/c1f20049ce3453eb/wal/00000000_000060b0.wal.lz4
2023-12-14 09:04:52        119 program/motherbrain/generations/c1f20049ce3453eb/wal/00000001_00000000.wal.lz4

Is the system working as intended? are we sending WAL segments to S3? I'm wondering why we don't see the "write wal segment" entries in our Litestream logs.

Thanks in advance for your help.

[hifi]

You are using an old version that didn't have verbose logging enabled by default. Try the latest release from GitHub.

[laser]

Gah, that'll do it. How embarrassing! Thanks for your help.