--resume and --revert silently lose changes read before the DML listener is registered #1793

#!/usr/bin/env bash
# Standalone reproduction: gh-ost --resume silently loses updates.
#
# Needs only docker, curl and sha256sum/shasum. Uses the official gh-ost release
# binary (checksum-verified) and the official mysql image. Nothing else.
#
# What it does:
#   1. Starts one MySQL server and creates repro.t (ROWS rows, a counter column v).
#   2. Starts an "app" that keeps running, in one transaction each:
#        UPDATE t SET v = v + 1 WHERE id = <random>;  INSERT INTO audit (tid) VALUES (<same id>);
#      so audit holds an independent, committed record of every update.
#   3. Runs gh-ost (--checkpoint, --postpone-cut-over-flag-file) to add a column.
#   4. SIGKILLs gh-ost just after a checkpoint (during the copy or during the postponed cut-over),
#      waits DOWNTIME seconds, then starts it again with the same flags plus --resume.
#   5. Stops the app, lets gh-ost cut over, and compares every row of the new table, and of the
#      old table gh-ost leaves behind (_t_del), with the audit table.
#
# Exit status: 1 = bug reproduced (gh-ost exited 0 but the new table lost committed updates),
#              0 = no data loss, 2 = inconclusive or setup error.
#
# Settings (environment variables):
#   HOOK_DELAY   seconds a gh-ost-on-validated hook sleeps; 0 = no hooks at all   (default 1)
#   KILL_PHASE   postponed | copy                                                (default postponed)
#   RESUME       1 = kill and resume; 0 = control: one uninterrupted run          (default 1)
#   DOWNTIME     seconds gh-ost stays down before --resume                        (default 3)
#   ROWS         rows in repro.t                        (default 100000; 600000 with KILL_PHASE=copy)
#   NICE_RATIO   gh-ost --nice-ratio, slows the row copy        (default 0; 5 with KILL_PHASE=copy)
#   GHOST_CPUS   if set, docker --cpus for the gh-ost container                   (default unset)
#   GHOST_ENV    extra "-e NAME=value" for the gh-ost container, e.g. GOMAXPROCS=1 (default unset)
#   EXTRA_ARGS   extra gh-ost flags, e.g. "--exact-rowcount"                       (default unset)
#   GHOST_BIN    path to a linux gh-ost binary to use instead of the official release
#   GHOST_VERSION, MYSQL_IMAGE, PREFIX, KEEP=1 (keep containers afterwards)
set -euo pipefail

GHOST_VERSION=${GHOST_VERSION:-v1.1.11}
MYSQL_IMAGE=${MYSQL_IMAGE:-mysql:8.0.45}
HOOK_DELAY=${HOOK_DELAY:-1}
KILL_PHASE=${KILL_PHASE:-postponed}
# KILL_PHASE=copy needs the row copy to outlast the first checkpoint (--checkpoint-seconds can't go below 10).
if [ "$KILL_PHASE" = copy ]; then
  ROWS=${ROWS:-600000}
  NICE_RATIO=${NICE_RATIO:-5}
else
  ROWS=${ROWS:-100000}
  NICE_RATIO=${NICE_RATIO:-0}
fi
RESUME=${RESUME:-1}
DOWNTIME=${DOWNTIME:-3}
GHOST_CPUS=${GHOST_CPUS:-}
GHOST_ENV=${GHOST_ENV:-}
EXTRA_ARGS=${EXTRA_ARGS:-}
GHOST_BIN=${GHOST_BIN:-}
P=${PREFIX:-ghrepro}
PW=reprorootpw

HERE=$(cd "$(dirname "$0")" && pwd)
WORK=$HERE/work-$P
RUN_ID=$(date +%Y%m%d-%H%M%S)-${LABEL:-run}-hook${HOOK_DELAY}-${KILL_PHASE}-resume${RESUME}
OUT=$HERE/results/$RUN_ID
mkdir -p "$OUT"

log() { printf '%s  %s\n' "$(date -u +%H:%M:%S)" "$*" | tee -a "$OUT/summary.txt"; }

cleanup() {
  [ -n "${WRITER_PID:-}" ] && kill "$WRITER_PID" 2>/dev/null || true
  for c in $P-ghost-1 $P-ghost-2; do docker logs "$c" >"$OUT/$c.log" 2>&1 || true; done
  if [ "${KEEP:-0}" != 1 ]; then
    docker rm -fv $P-mysql $P-ghost-1 $P-ghost-2 >/dev/null 2>&1 || true
    docker network rm $P-net >/dev/null 2>&1 || true
  fi
}
trap cleanup EXIT

die() { log "ERROR: $*"; exit 2; }

sql() { docker exec -i -e MYSQL_PWD=$PW $P-mysql mysql -h127.0.0.1 -uroot -N -B "$@"; }
sqlt() { docker exec -i -e MYSQL_PWD=$PW $P-mysql mysql -h127.0.0.1 -uroot -t "$@"; }
mark() { sql repro -e "INSERT INTO marks (name) VALUES ('$1')" </dev/null; }

# --- gh-ost binary: official release, checksum-verified --------------------------------------
case "$(docker info --format '{{.Architecture}}')" in
  aarch64|arm64) A=arm64 ;;
  x86_64|amd64)  A=amd64 ;;
  *) die "unsupported docker architecture" ;;
esac
BIN=$HERE/gh-ost-$GHOST_VERSION-linux-$A
if [ ! -x "$BIN/gh-ost" ]; then
  mkdir -p "$BIN"
  base=https://github.com/github/gh-ost/releases/download/$GHOST_VERSION
  curl -fsSL -o "$BIN/gh-ost-linux-$A.tar.gz" "$base/gh-ost-linux-$A.tar.gz"
  curl -fsSL -o "$BIN/SHA256SUMS" "$base/SHA256SUMS"
  ( cd "$BIN" && grep " gh-ost-linux-$A.tar.gz\$" SHA256SUMS > want.sum &&
    { sha256sum -c want.sum 2>/dev/null || shasum -a 256 -c want.sum; } &&
    tar -xzf "gh-ost-linux-$A.tar.gz" gh-ost )
fi

# --- fresh MySQL and work dir ----------------------------------------------------------------
docker rm -fv $P-mysql $P-ghost-1 $P-ghost-2 >/dev/null 2>&1 || true
docker network rm $P-net >/dev/null 2>&1 || true
rm -rf "$WORK" && mkdir -p "$WORK/hooks"
cp "${GHOST_BIN:-$BIN/gh-ost}" "$WORK/gh-ost"

docker network create $P-net >/dev/null
docker run -d --name $P-mysql --network $P-net -e MYSQL_ROOT_PASSWORD=$PW "$MYSQL_IMAGE" \
  --server-id=1 --log-bin=binlog --binlog-format=ROW --binlog-row-image=FULL >/dev/null
for _ in $(seq 120); do sql -e 'SELECT 1' </dev/null >/dev/null 2>&1 && break; sleep 1; done
sql -e 'SELECT 1' </dev/null >/dev/null || die "mysql did not start"

log "gh-ost $("$WORK/gh-ost" --version 2>/dev/null || docker run --rm -v "$WORK:/work" --entrypoint /work/gh-ost "$MYSQL_IMAGE" --version) ($A), $MYSQL_IMAGE ($(sql -e 'SELECT @@version' </dev/null)), ROWS=$ROWS HOOK_DELAY=$HOOK_DELAY KILL_PHASE=$KILL_PHASE RESUME=$RESUME DOWNTIME=$DOWNTIME NICE_RATIO=$NICE_RATIO GHOST_CPUS=${GHOST_CPUS:-none} GHOST_ENV=${GHOST_ENV:-none} EXTRA_ARGS=${EXTRA_ARGS:-none}"

sql <<SQL
CREATE DATABASE repro;
CREATE TABLE repro.t (
  id  INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
  v   INT NOT NULL DEFAULT 0,
  pad VARCHAR(200) NOT NULL DEFAULT ''
);
CREATE TABLE repro.audit (
  seq BIGINT NOT NULL AUTO_INCREMENT PRIMARY KEY,
  tid INT NOT NULL,
  ts  DATETIME(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6),
  KEY (tid)
);
CREATE TABLE repro.marks (
  name VARCHAR(40) NOT NULL PRIMARY KEY,
  ts   DATETIME(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6)
);
SET SESSION cte_max_recursion_depth = 100000000;
INSERT INTO repro.t (pad)
  WITH RECURSIVE s (n) AS (SELECT 1 UNION ALL SELECT n + 1 FROM s WHERE n < $ROWS)
  SELECT REPEAT('x', 200) FROM s;
SQL
log "created repro.t with $(sql repro -e 'SELECT COUNT(*) FROM t' </dev/null) rows"

# --- the app: random single-row updates, each recorded in audit in the same transaction -------
writer() {
  while [ ! -f "$WORK/stop-writer" ]; do
    id=$(( (RANDOM * 32768 + RANDOM) % ROWS + 1 ))
    echo "BEGIN; UPDATE t SET v = v + 1 WHERE id = $id; INSERT INTO audit (tid) VALUES ($id); COMMIT;"
    sleep 0.01
  done
}
writer | docker exec -i -e MYSQL_PWD=$PW $P-mysql mysql -h127.0.0.1 -uroot repro &
WRITER_PID=$!
log "app writer started"

# --- gh-ost ---------------------------------------------------------------------------------
if [ "$HOOK_DELAY" != 0 ]; then
  cat >"$WORK/hooks/gh-ost-on-validated" <<HOOK
#!/bin/sh
echo "\$(date -u +%H:%M:%S.%N) on-validated hook start (sleeping $HOOK_DELAY s)" >> /work/hooks.log
sleep $HOOK_DELAY
echo "\$(date -u +%H:%M:%S.%N) on-validated hook end" >> /work/hooks.log
HOOK
  chmod +x "$WORK/hooks/gh-ost-on-validated"
  HOOK_ARGS=(--hooks-path=/work/hooks)
else
  HOOK_ARGS=()
fi
touch "$WORK/postpone-cut-over.flag"

GHOST_ARGS=(
  --host=$P-mysql --port=3306 --user=root --password=$PW
  --database=repro --table=t
  --alter="ADD COLUMN note VARCHAR(20) NULL"
  --allow-on-master
  --checkpoint --checkpoint-seconds=10
  --postpone-cut-over-flag-file=/work/postpone-cut-over.flag
  --chunk-size=1000
  --verbose
  --execute
)
if [ "$NICE_RATIO" != 0 ]; then GHOST_ARGS+=(--nice-ratio="$NICE_RATIO"); fi
# shellcheck disable=SC2206
GHOST_ARGS+=(${HOOK_ARGS[@]+"${HOOK_ARGS[@]}"} $EXTRA_ARGS)

start_ghost() { # name, extra args...
  local name=$1; shift
  local opts=(-d --name "$name" --network $P-net -v "$WORK:/work" --entrypoint /work/gh-ost)
  [ -n "$GHOST_CPUS" ] && opts+=(--cpus "$GHOST_CPUS")
  [ -n "$GHOST_ENV" ] && opts+=(-e "$GHOST_ENV")
  docker run "${opts[@]}" "$MYSQL_IMAGE" "${GHOST_ARGS[@]}" "$@" >/dev/null
}

count_log() { docker logs "$1" 2>&1 | grep -c -- "$2" || true; }

wait_log() { # container, pattern, [min count], [timeout seconds]
  local c=$1 pat=$2 n=${3:-1} t=${4:-600} start=$SECONDS
  while [ "$(count_log "$c" "$pat")" -lt "$n" ]; do
    [ "$(docker inspect -f '{{.State.Running}}' "$c")" = true ] || { docker logs --tail 20 "$c"; die "$c exited while waiting for '$pat'"; }
    [ $((SECONDS - start)) -lt "$t" ] || die "timed out waiting for '$pat' in $c"
    sleep 0.2
  done
}

mark run1_start
start_ghost $P-ghost-1
log "gh-ost run 1 started"
FINAL=$P-ghost-1

if [ "$RESUME" = 1 ]; then
  if [ "$KILL_PHASE" = postponed ]; then
    wait_log $P-ghost-1 'Row copy complete'
    log "run 1: row copy complete, cut-over postponed"
  fi
  n=$(count_log $P-ghost-1 'checkpoint success')
  wait_log $P-ghost-1 'checkpoint success' $((n + 1))
  log "run 1: $(docker logs $P-ghost-1 2>&1 | grep 'checkpoint success' | tail -1 | sed 's/.*checkpoint success/checkpoint success/')"
  if [ "$KILL_PHASE" = copy ] && [ "$(count_log $P-ghost-1 'Row copy complete')" -gt 0 ]; then
    die "row copy finished before the first checkpoint; raise ROWS or NICE_RATIO for KILL_PHASE=copy"
  fi
  sleep 1
  docker kill $P-ghost-1 >/dev/null   # SIGKILL, like a crashed host or an evicted pod
  mark killed
  log "run 1: SIGKILLed 1 s after that checkpoint; app keeps writing; down for $DOWNTIME s"
  sleep "$DOWNTIME"

  mark run2_start
  start_ghost $P-ghost-2 --resume
  log "gh-ost run 2 (--resume) started"
  wait_log $P-ghost-2 'Row copy complete'
  wait_log $P-ghost-2 'postponing cut-over'
  log "run 2: $(docker logs $P-ghost-2 2>&1 | grep -m1 'Resuming from checkpoint' | sed 's/.*Resuming/Resuming/')"
  log "run 2: row copy complete, cut-over postponed"
  FINAL=$P-ghost-2
else
  wait_log $P-ghost-1 'Row copy complete'
  wait_log $P-ghost-1 'postponing cut-over'
  log "run 1: row copy complete, cut-over postponed (control: no interruption)"
fi

sleep 3
touch "$WORK/stop-writer"
wait "$WRITER_PID" || die "app writer failed"
WRITER_PID=
mark writer_stopped
log "app writer stopped after $(sql repro -e 'SELECT COUNT(*) FROM audit' </dev/null) committed updates"

sleep 2
rm -f "$WORK/postpone-cut-over.flag"
log "postpone flag removed; waiting for cut-over"
rc=$(docker wait $FINAL)
log "gh-ost exit code: $rc; last line: $(docker logs $FINAL 2>&1 | grep -E 'Done migrating|FATAL|ERROR' | tail -1)"

# --- verify ---------------------------------------------------------------------------------
sqlt repro >>"$OUT/summary.txt" <<'SQL'
SELECT name, ts FROM marks ORDER BY ts;
SQL
RESULT=$(sql repro <<'SQL'
WITH expected AS (SELECT tid, COUNT(*) AS n FROM audit GROUP BY tid)
SELECT
  (SELECT COUNT(*) FROM t),
  (SELECT COUNT(*) FROM _t_del),
  (SELECT COUNT(*) FROM expected e JOIN t     x ON x.id = e.tid WHERE x.v <> e.n),
  (SELECT COALESCE(SUM(e.n - x.v), 0) FROM expected e JOIN t x ON x.id = e.tid WHERE x.v <> e.n),
  (SELECT COUNT(*) FROM expected e JOIN _t_del x ON x.id = e.tid WHERE x.v <> e.n),
  (SELECT COUNT(*) FROM t x LEFT JOIN expected e ON e.tid = x.id WHERE e.tid IS NULL AND x.v <> 0);
SQL
)
read -r new_rows old_rows new_wrong new_lost old_wrong new_extra <<<"$RESULT"
log "rows: new t=$new_rows, old _t_del=$old_rows"
log "old table _t_del vs audit: $old_wrong rows wrong (sanity check, must be 0)"
log "new table t      vs audit: $new_wrong rows wrong, $new_lost updates missing, $new_extra rows with unexpected updates"
if [ "$new_wrong" -gt 0 ]; then
  sqlt repro >>"$OUT/summary.txt" <<'SQL'
-- Lost updates: rows where the new table holds none of the row's committed updates.
SELECT COUNT(*) AS lost_updates_on_untouched_rows, MIN(a.ts) AS first_committed, MAX(a.ts) AS last_committed
FROM audit a JOIN t x ON x.id = a.tid WHERE x.v = 0;
-- Which rows: ids of rows whose value in the new table is wrong.
WITH expected AS (SELECT tid, COUNT(*) AS n FROM audit GROUP BY tid)
SELECT MIN(x.id) AS lowest_wrong_id, MAX(x.id) AS highest_wrong_id
FROM expected e JOIN t x ON x.id = e.tid WHERE x.v <> e.n;
-- A few examples: committed updates per audit vs the value in the new and old tables.
WITH expected AS (SELECT tid, COUNT(*) AS n FROM audit GROUP BY tid)
SELECT e.tid AS id, e.n AS committed_updates, x.v AS v_in_new_t, o.v AS v_in_old_t_del
FROM expected e JOIN t x ON x.id = e.tid JOIN _t_del o ON o.id = e.tid
WHERE x.v <> e.n ORDER BY e.tid LIMIT 5;
SQL
fi
[ -f "$WORK/hooks.log" ] && cp "$WORK/hooks.log" "$OUT/hooks.log"

if [ "$rc" = 0 ] && [ "$new_wrong" -gt 0 ] && [ "$old_wrong" = 0 ]; then
  log "RESULT: BUG REPRODUCED: gh-ost exited 0 but the new table lost $new_lost committed updates ($new_wrong rows)"
  exit 1
elif [ "$rc" = 0 ] && [ "$new_wrong" = 0 ] && [ "$old_wrong" = 0 ] && [ "$new_extra" = 0 ]; then
  log "RESULT: no data loss"
  exit 0
else
  log "RESULT: inconclusive (gh-ost rc=$rc, new_wrong=$new_wrong, old_wrong=$old_wrong, extra=$new_extra)"
  exit 2
fi