Skip to content

Commit 7f10ca4

Browse files
markhannummarkhannum
committed
test: verify the log record checksum chain
Checks each record's prevcksum against the previous record's cksum, in steady state, across a log file rollover, and across a bounce. pushlogs is asynchronous and master-only, so the rollover is polled for rather than assumed. Every node is flushed at the end: a flush that hangs is itself a bug, and failing here beats letting the harness's own silent flush time out and blame the datafiles. Signed-off-by: Mark Hannum <mhannum@bloomberg.net>
1 parent 8595200 commit 7f10ca4

3 files changed

Lines changed: 182 additions & 0 deletions

File tree

‎tests/log_cksum_prev.test/Makefile‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
ifeq ($(TESTSROOTDIR),)
2+
include ../testcase.mk
3+
else
4+
include $(TESTSROOTDIR)/testcase.mk
5+
endif
6+
ifeq ($(TEST_TIMEOUT),)
7+
export TEST_TIMEOUT=5m
8+
endif

‎tests/log_cksum_prev.test/lrl.options‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,4 @@
1+
# Small log files so the rollover case is reached quickly.
2+
# LOGFILESIZE must be >= 4 * LOGMEMSIZE.
3+
setattr LOGMEMSIZE 131072
4+
setattr LOGFILESIZE 1048576

‎tests/log_cksum_prev.test/runit‎

Lines changed: 170 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,170 @@
1+
#!/usr/bin/env bash
2+
bash -n "$0" | exit 1
3+
source ${TESTSROOTDIR}/tools/cluster_utils.sh
4+
a_dbn=$1
5+
kill_wait_time=10
6+
7+
# Verify the prev-record checksum chain is unbroken, including across a log
8+
# file rollover and a bounce (which re-derives the chain head at recovery).
9+
10+
function failif
11+
{
12+
if [[ $1 -ne 0 ]]; then
13+
echo "FAILED: $2"
14+
exit 1
15+
fi
16+
}
17+
18+
function scalar
19+
{
20+
cdb2sql ${CDB2_OPTIONS} --tabs $a_dbn default "$1" 2>/dev/null
21+
}
22+
23+
# Check each record's prevcksum against the previous record's cksum.
24+
# Untagged records report NULL and are skipped.
25+
function verify_chain
26+
{
27+
local out
28+
out=$(cdb2sql ${CDB2_OPTIONS} --tabs $a_dbn default \
29+
"select lsn, cksum, prevcksum from comdb2_transaction_logs" 2>/dev/null | awk -F'\t' '
30+
{
31+
n++
32+
if (have && $3 != "NULL" && $3 != prev) {
33+
breaks++
34+
if (breaks <= 5)
35+
print " break at " $1 ": prevcksum=" $3 " but " prevlsn " cksum=" prev
36+
}
37+
if ($3 != "NULL")
38+
tagged++
39+
prev = $2; prevlsn = $1; have = 1
40+
}
41+
END { print "records=" n " tagged=" tagged+0 " breaks=" breaks+0 }')
42+
echo "$1: $out"
43+
echo "$out" | grep -q "breaks=0"
44+
failif $? "$1: checksum chain is broken"
45+
echo "$out" | grep -q "tagged=0"
46+
if [[ $? -eq 0 ]]; then
47+
echo "FAILED: $1: no record carried a prevcksum"
48+
exit 1
49+
fi
50+
}
51+
52+
function insert_rows
53+
{
54+
local i
55+
for ((i = 0; i < $1; i++)); do
56+
cdb2sql ${CDB2_OPTIONS} $a_dbn default \
57+
"insert into t values($i, '$(printf 'x%.0s' {1..200})')" >/dev/null 2>&1
58+
done
59+
}
60+
61+
function set_cksum_prev
62+
{
63+
local node
64+
for node in ${CLUSTER:-$(hostname)}; do
65+
cdb2sql ${CDB2_OPTIONS} --host $node $a_dbn \
66+
"exec procedure sys.cmd.send('log_cksum_prev $1')" >/dev/null 2>&1
67+
done
68+
}
69+
70+
function untagged_count
71+
{
72+
scalar "select count(*) from comdb2_transaction_logs where prevcksum is null"
73+
}
74+
75+
function bounce
76+
{
77+
if [[ -n "$CLUSTER" ]]; then
78+
for node in $CLUSTER; do
79+
kill_restart_node $node $kill_wait_time &
80+
done
81+
sleep $kill_wait_time
82+
for node in $CLUSTER; do
83+
out=$(cdb2sql ${CDB2_OPTIONS} --tabs --host $node $a_dbn 'select 1' 2>/dev/null)
84+
while [[ "$out" != "1" ]]; do
85+
sleep $kill_wait_time
86+
out=$(cdb2sql ${CDB2_OPTIONS} --tabs --host $node $a_dbn 'select 1' 2>/dev/null)
87+
done
88+
done
89+
else
90+
kill_restart_node $(hostname) $kill_wait_time
91+
fi
92+
}
93+
94+
cdb2sql ${CDB2_OPTIONS} $a_dbn default "create table t(i int, c char(300))" >/dev/null 2>&1
95+
failif $? "create table"
96+
97+
insert_rows 200
98+
verify_chain "steady state"
99+
100+
# Roll to a new log file: LOGP is excluded from the chain, so the first
101+
# record of the new file must chain to the last record of the old one.
102+
# pushlogs is asynchronous (it spawns a writer thread on the master), so
103+
# it must go to the master, and the rollover must be polled for.
104+
master=$(get_master)
105+
before=$(scalar "select max(lsnfile) from comdb2_transaction_logs")
106+
cdb2sql ${CDB2_OPTIONS} --host $master $a_dbn \
107+
"exec procedure sys.cmd.send('pushlogs $((before + 1))')" >/dev/null 2>&1
108+
deadline=$((SECONDS + 120))
109+
after=$(scalar "select max(lsnfile) from comdb2_transaction_logs")
110+
while [[ "$after" -le "$before" && $SECONDS -lt $deadline ]]; do
111+
sleep 2
112+
after=$(scalar "select max(lsnfile) from comdb2_transaction_logs")
113+
done
114+
echo "log file: $before -> $after"
115+
if [[ "$after" -le "$before" ]]; then
116+
echo "FAILED: log did not roll over, rollover case not covered"
117+
exit 1
118+
fi
119+
insert_rows 50
120+
verify_chain "after log rollover"
121+
122+
# __log_recover() re-derives the chain head from the tail of the log.
123+
bounce
124+
insert_rows 50
125+
verify_chain "after bounce"
126+
127+
# Toggling the tunable mid-run leaves tagged and untagged records mixed in one
128+
# log. last_cksum advances over every record whether or not it is tagged, so a
129+
# tagged record written after the tunable comes back on has to chain to the
130+
# untagged record before it. That boundary is the point of this section.
131+
set_cksum_prev 0
132+
before_off=$(untagged_count)
133+
insert_rows 50
134+
after_off=$(untagged_count)
135+
echo "untagged records: $before_off -> $after_off"
136+
if [[ "$after_off" -le "$before_off" ]]; then
137+
echo "FAILED: disabling log_cksum_prev did not stop records being tagged"
138+
exit 1
139+
fi
140+
verify_chain "with tunable off"
141+
142+
set_cksum_prev 1
143+
insert_rows 50
144+
after_on=$(untagged_count)
145+
echo "untagged records after re-enabling: $after_on"
146+
if [[ "$after_on" -gt "$after_off" ]]; then
147+
echo "FAILED: re-enabling log_cksum_prev did not resume tagging ($after_off -> $after_on)"
148+
exit 1
149+
fi
150+
verify_chain "after re-enabling"
151+
152+
# Flush every node so the harness's post-test physical verify sees fully
153+
# written files. A flush that hangs here (seen once on a freshly
154+
# re-elected master) is itself a bug: fail loudly rather than let the
155+
# harness's silent flush time out and blame the datafiles.
156+
for node in ${CLUSTER:-$(hostname)}; do
157+
ok=1
158+
for attempt in 1 2; do
159+
timeout 30 cdb2sql ${CDB2_OPTIONS} --tabs --host $node $a_dbn \
160+
"exec procedure sys.cmd.send('flush')" >/dev/null 2>&1 && ok=0 && break
161+
echo "flush attempt $attempt timed out on $node"
162+
done
163+
if [[ $ok -ne 0 ]]; then
164+
echo "FAILED: flush hung on $node"
165+
exit 1
166+
fi
167+
done
168+
169+
echo "SUCCESS"
170+
exit 0

0 commit comments

Comments
 (0)