Replicate only on WAL changes

[mtlynch]

Thanks again for this software!

I'm using litestream with a service that has infrequent database writes (like a handful of times per day).

I noticed my AWS dashboard reporting many PUTs and revisited the documentation and realized that litestream replicates the WAL every 10s.

A nice to have feature would be if litestream skips the WAL replication if no local changes have occurred since last sync.

An even nicer feature for my scenario would be a "sync only on write" mode where instead of replicating every N seconds, it replicates immediately after each change to the WAL, but otherwise does not replicate.

Low priority since my understanding is that even 300k S3 PUTs is only ~$1.50/month, but it'd be cool if litestream could run completely in the free tier for infrequent write scenearios.

[benbjohnson]

Hmm, it should only call PUT when there's a change so that's definitely a bug. I'll take a look to see if I can reproduce.

I plan on switching out the polling for something like fsnotify to allow faster pushes of WAL changes. This is important for live replicas (#8) since they need low latency replication.

[mtlynch]

Thanks for checking it out!

If you want to try it on the service where I'm observing it, it's pretty easy to run my service locally under Docker:

# Fill these in
AWS_ACCESS_KEY_ID=YOUR-ACCESS-ID
AWS_SECRET_ACCESS_KEY=YOUR-SECRET-ACCESS-KEY
AWS_REGION=YOUR-REGION
DB_REPLICA_URL=s3://your-bucket-name/db

cd $(mktemp -d)
git clone https://github.com/mtlynch/logpaste.git .

docker build -t logpaste . && \
docker run \
  -e "AWS_ACCESS_KEY_ID=${AWS_ACCESS_KEY_ID}" \
  -e "AWS_SECRET_ACCESS_KEY=${AWS_SECRET_ACCESS_KEY}" \
  -e "AWS_REGION=${AWS_REGION}" \
  -e "DB_REPLICA_URL=${DB_REPLICA_URL}" \
  logpaste

It will create a web interface listening on port 3001. It only writes to the database when you visit the web dashboard, enter something in the textarea, and hit "upload."

litestream-relevant code:

https://github.com/mtlynch/logpaste/blob/7425cf63a5fbd6b65bef13236b09028c28947924/docker_entrypoint#L9L33

[benbjohnson]

@mtlynch I'm getting this error since the database doesn't exist on my bucket:

$ docker run   -e "AWS_ACCESS_KEY_ID=${AWS_ACCESS_KEY_ID}"   -e "AWS_SECRET_ACCESS_KEY=${AWS_SECRET_ACCESS_KEY}"   -e "AWS_REGION=${AWS_REGION}"   -e "DB_REPLICA_URL=${DB_REPLICA_URL}"   logpaste
+ litestream restore -v /app/data/store.db
no matching backups found

I tried reproducing the issue with a local generation tool that I have but I only saw PUT calls when data was being written. There are metrics in Litestream you can enable if you set a addr in the YAML configuration:

addr: :9090

And then I ran a watch on it:

$ watch -n 1 "curl -s localhost:9090/metrics | grep litestream_s3_operation_total"

That shows a count of the GET/LIST/PUT/etc calls.

I'd be surprised if it's written when there's no writes to the database as the PUT files are just a collection of new WAL frames. If the underlying -wal file doesn't change then there's not anything Litestream should be pushing up.

[mtlynch]

Hmm, I'm not sure how to get the metrics endpoint to run. I think my config is right, but curl sees nothing:

$ cat /home/mike/litestream.yml 
# AWS credentials
access-key-id: redacted
secret-access-key: redacted
region: us-east-2
addr: :9090

dbs:
  - path: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db
    replicas:
      - url: s3://scratch.tinypilotkvm.com/db

$ litestream replicate -trace /dev/stdout -config /home/mike/litestream.yml "${PWD}/data/store.db" s3://scratch.tinypilotkvm.com/db
litestream v0.3.2
initialized db: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db
replicating to: name="s3" type="s3" bucket="scratch.tinypilotkvm.com" path="db" region=""
2021/02/25 02:02:29 db.go:732: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: sync: info=litestream.syncInfo{generation:"522a4671017a1edb", dbModTime:time.Time{wall:0xeadf8c1, ext:63749815127, loc:(*time.Location)(0x173a8a0)}, walSize:82432, walModTime:time.Time{wall:0xf65138c, ext:63749815127, loc:(*time.Location)(0x173a8a0)}, shadowWALPath:"/home/mike/go/src/github.com/mtlynch/logpaste/data/.store.db-litestream/generations/522a4671017a1edb/wal/00000001.wal", shadowWALSize:4152, restart:false, reason:""}
2021/02/25 02:02:29 db.go:989: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: copy-shadow: /home/mike/go/src/github.com/mtlynch/logpaste/data/.store.db-litestream/generations/522a4671017a1edb/wal/00000001.wal
2021/02/25 02:02:29 db.go:1054: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: copy-shadow: break: salt mismatch
2021/02/25 02:02:29 db.go:802: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: sync: ok
2021/02/25 02:02:30 db.go:732: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: sync: info=litestream.syncInfo{generation:"522a4671017a1edb", dbModTime:time.Time{wall:0xeadf8c1, ext:63749815127, loc:(*time.Location)(0x173a8a0)}, walSize:82432, walModTime:time.Time{wall:0xf65138c, ext:63749815127, loc:(*time.Location)(0x173a8a0)}, shadowWALPath:"/home/mike/go/src/github.com/mtlynch/logpaste/data/.store.db-litestream/generations/522a4671017a1edb/wal/00000001.wal", shadowWALSize:4152, restart:false, reason:""}
2021/02/25 02:02:30 db.go:989: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: copy-shadow: /home/mike/go/src/github.com/mtlynch/logpaste/data/.store.db-litestream/generations/522a4671017a1edb/wal/00000001.wal
2021/02/25 02:02:30 db.go:1054: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: copy-shadow: break: salt mismatch
2021/02/25 02:02:30 db.go:802: /home/mike/go/src/github.com/mtlynch/logpaste/data/store.db: sync: ok

$ curl localhost:9090
curl: (7) Failed to connect to localhost port 9090: Connection refused

Those salt mismatch errors keep repeating. Is that expected? Full logs

[benbjohnson]

@mtlynch Hmm, that looks right for the addr field. It's odd that it's not showing this line after initialization:

serving metrics on http://localhost:9090/metrics

I was testing on main before but I pulled down v0.3.2 and tested against that binary and I'm still seeing it only PUT when I submit the form on the logpaste site.

As for salt mismatch, that's normal. The WAL acts like a circular buffer and the "salt mismatch" just means that Litestream has reached the end of the current buffer position and is stopping.

[mtlynch]

Hmm, that looks right for the addr field. It's odd that it's not showing this line after initialization:

I realized that's a separate issue. I just filed #85 to track.

I'll tinker more with it now that I figured out how to get metrics to serve. Something's going crazy, though, because this is the only app I'm using with AWS, and I've generated 3.2M (edit: 3.2k, see below) PUT requests to S3:

[mtlynch]

I got metrics working and it's showing only small numbers of all S3 operations. Meanwhile, S3 keeps reporting hundreds of thousands of PUTs every day, so I'm not sure what's going on.

I'm going to cycle my IAM keys in case there's a zombie process somewhere going nuts. I'll reopen this bug if it looks like litestream is indeed generating too many requests.

[mtlynch]

I realized I was misreading the numbers. I thought it was 1,310,000 (1.3M), but it's actually 1,310 (1.3k). I'm not sure why AWS lists numbers of requests as a decimal to three places...

It's still higher than I expect the numbers to be, but not as dramatically as I thought.