crash in default fsync=off mode corrupts whole binlog files

[ysmolski]

I never expected that it would be so easy reproduce this. But anyway. Start beanstalkd in a loop:

#!/usr/bin/env bash

trap "kill 0" EXIT SIGINT SIGTERM
set -e
rm -rf ./wal/*
while true; do
    ../beanstalkd/beanstalkd -l 127.0.0.1 -p 11000 -b ./wal -s 1024000 -V &
    pid=$!
    sleep 0.5
    kill -TERM $pid
    wait
done

Launch a producer of jobs that pushes them one by one. I have done it through Python scripts, but anything will do.
After couple of seconds I get this:

pid 84155
bind 3 127.0.0.1:11000
accept 11
pid 84157
bind 3 127.0.0.1:11000
../beanstalkd/beanstalkd: ./wal/binlog.149: unknown version: 0
../beanstalkd/beanstalkd: Errors reading one or more WAL files.
../beanstalkd/beanstalkd: Continuing. You may be missing data.
accept 11
pid 84159
bind 3 127.0.0.1:11000
../beanstalkd/beanstalkd: ./wal/binlog.149: unknown version: 0
../beanstalkd/beanstalkd: Errors reading one or more WAL files.
../beanstalkd/beanstalkd: Continuing. You may be missing data.
accept 11
pid 84161
bind 3 127.0.0.1:11000
../beanstalkd/beanstalkd: ./wal/binlog.149: unknown version: 0
../beanstalkd/beanstalkd: Errors reading one or more WAL files.
../beanstalkd/beanstalkd: Continuing. You may be missing data.

beanstalk was able to start in that mode, but it kept trying to read the same file.
I tried to delete binlog.149 and got:

pid 84241
bind 3 127.0.0.1:11000
../beanstalkd/beanstalkd: walg.c:459 in walread: open ./wal/binlog.149: No such file or directory

More time passed, more errors were accumulated:

../beanstalkd/beanstalkd: walg.c:459 in walread: open ./wal/binlog.149: No such file or directory
../beanstalkd/beanstalkd: ./wal/binlog.233: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.274: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.288: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.295: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.322: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.404: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.416: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.455: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.460: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.466: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.483: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.490: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.494: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.519: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.525: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.530: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.546: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.551: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.567: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.571: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.575: unknown version: 0
./wal/binlog.581:0: unexpected EOF reading 4 bytes (got 0): version
../beanstalkd/beanstalkd: ./wal/binlog.591: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.597: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.602: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.607: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.616: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.636: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.644: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.769: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.775: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.779: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.793: unknown version: 0
../beanstalkd/beanstalkd: ./wal/binlog.796: unknown version: 0
../beanstalkd/beanstalkd: Errors reading one or more WAL files.
../beanstalkd/beanstalkd: Continuing. You may be missing data.

I stopped generating crashes and I tried to consume all the jobs:

% l wal
total 2000
-r--------  1 thorn  staff   1.0M Aug 14 08:51 binlog.1721
-rw-------  1 thorn  staff     0B Aug 14 08:31 lock

All this on mac where fsync cannot be turned on due bug #539 . These errors mean that log file was not read and was completely ignored, everything in that file was lost most probably.

After I have forced beanstalk to fsync on macOS and run it with "-f0", the rate of new errors was reduced, but they were still present.

The somewhat reliable way to run beanstalkd is to have "-f 0", fsync on every command. That means very bad performance. The default setting of never fsync-ing is a bad idea. This way user can lose the whole binlog file instead of just couple of milliseconds of data.

Let's look at the benchmarks to get an idea of good default value for -f:

ctbench_put_delete_1024			    5000	    321840 ns/op	   4.83 MB/s
ctbench_put_delete_wal_1024_fsync_000ms	     100	  10783976 ns/op	   0.10 MB/s
ctbench_put_delete_wal_1024_fsync_050ms	    3000	    401186 ns/op	   3.01 MB/s
ctbench_put_delete_wal_1024_fsync_200ms	    3000	    372918 ns/op	   3.04 MB/s
ctbench_put_delete_wal_1024_no_fsync	    3000	    358677 ns/op	   3.05 MB/s

ctbench_put_delete_8192			    5000	    389117 ns/op	  37.42 MB/s
ctbench_put_delete_wal_8192_fsync_000ms	     200	   9642472 ns/op	   1.50 MB/s
ctbench_put_delete_wal_8192_fsync_050ms	    2000	    555952 ns/op	  16.20 MB/s
ctbench_put_delete_wal_8192_fsync_200ms	    2000	    524707 ns/op	  16.30 MB/s
ctbench_put_delete_wal_8192_no_fsync	    3000	    505258 ns/op	  23.37 MB/s

Performance degrades only for the fsync period -> zero. 50ms is a good enough tradeoff between performance and the amount of data lost in a crash.

[ysmolski]

My assumption was wrong about the whole binlog being corrupted. The only corrupted part is the last written job or the empty log file (zeroed files). And that is totally okay since write was prevented by the kill, that record was not written in full into the file and will be ignored on the next start. Command for the jobs that was not written in full into disk won't return anything, client will not get ACK, so he must retry later.

Phew. 🐳

default fsync period with small values (<50ms) still sounds good because it does not hurt performance, but decreases amount of lost data because of machine crash.

/CC @tomponline @sergeyklay

[ysmolski]

Closing as there is no thing to be done here and I have created #548 for default "-f"/-F value.