[#1208] Restart a directory server during the load of the replication convergence run, in rows of its own (#1233)
Part of #1208: the first disturbance, a directory server restarted
during the load, and what every later one needs. The others (a
replication server killed or stopped, failover, scale in and out) follow
one PR at a time; this one does not close the issue.
## What it does
- **A disturbance per run** (`run.sh`, `lib.sh`): `DISTURBANCE=<name>`
sources `disturb-<name>.sh` next to the run, which names the `DISTURBED`
server and defines `disturb`, which takes the topology down in one way
`DISTURB_AT` seconds into the load (a third of it by default) and
returns once the server serves again, and `settle`, which `run.sh` calls
after the load, before the wait for convergence (`DISTURB_TIMEOUT`, 900
s, for each). `none`, the default, is the base run as before. A
disturbed run takes 900 s of load by default, as its CI rows do; the 120
s of the base run would leave no load after a restart. An unknown name
or a `DISTURB_AT` outside the load ends the run with 2 before anything
starts. The convergence time still counts from the end of the load
(`wait_converged [<start>]`).
- **`restart-ds`** (`disturb-restart-ds.sh`): `docker restart -t 120` of
the second directory server - the default 10 s would kill a server that
stops under load, which is another disturbance - then the wait until the
server logs that it started (msgID 135) after the restart
(`started_since`, `docker logs --since`). Not until its container is
healthy again: the probe of the health check is a JVM of its own and
does not get through its 30 s on a loaded runner (below). `settle` waits
for its join, which the image runs on every start, to end, as
`topology_up` waits for it. In `combined` its replication server
restarts with it.
- **Load in segments** (`load.sh`): the clients of the restarted server
get `--maxDuration DISTURB_AT` and end on their own before the restart,
so that it cuts none of their operations off: one that already had its
CSN would read as a lost change. Once the server serves again, a second
segment of clients takes the rest of the load. It adds entries under a
uid prefix of its own (the 100 newest of the first segment are still
there) and writes values that start with its own name (`cv-d1-2-…`): the
rate tools are seeded alike, and the second segment would otherwise
write the values of the first again, in the same order. `check_client`
checks each client against the seconds it was to run; a server that
serves again too late to take 30 s of load fails the run.
- **Changelogs** (`changelog-gaps.py`, docstring only): a restart leaves
no gap of its own, so the check reads the changes of a restarted server
as it reads the others, and a gap around the restart is a lost change,
the kind #1195 lost. A directory server that stops numbers its
`ReplicaOfflineMsg` like a change, but the message does not enter the
`ServerState` of the replica
(`ReplicaOfflineMsg.contributesToDomainState()` is false), from which
`CSNGenerator` numbers again on the start: the first change after the
restart takes the sequence number of the message again, at a later time.
#1192 wrote the opposite into the docstring - that a restart would read
as a lost change - and that was wrong: in run 39834888428 the changes of
the restarted `cv-d1` were numbered 1 to 139792 without a gap.
- **Errors logs** (`assert-converged.sh`): a server that starts on a
loaded runner fails handshakes, the other end giving up first, and
connects elsewhere a few seconds later. So `disturb` opens a window over
the errors log of every server before the restart and closes it 10 s
after the restarted server serves again (`window_open`, `window_close`:
line counts, as `mark_logs` takes them). The 10 s cover a handshake the
start began and a peer's wait for the domain lock, of up to 8 s, after
which it logs 145. `replication_errors` expects such a handshake in a
window: msgID 178 or 179 at ERROR (a directory server or a replication
server that disconnected in the handshake, logged by the replication
server it connected to), 145 at ERROR (a replication server whose
connection crossed one the other way and lost the domain lock to it,
which `lockDomainWithTimeout` does on purpose), or
`SSLHandshakeException(Remote host terminated the handshake)` at WARNING
(a peer that closed the handshake once its read timed out). 145 is a
warning by its descriptor, and 178 and 179 are logged at WARNING by the
other end: `abortStart` logs them all at ERROR, which #1241 is about. A
window expects them on any server, not only on the connections of the
restarted one: 178 and 179 name servers by id alone. Those go to
`logs/<node>.expected` and to the summary; outside a window, and
anything else inside one, they fail the run as before. An errors log
that cannot be read stops the run: `errors_lines` reads it with a
redirect, where `cat … | wc -l` counted 0 lines and exited 0, and
`window_open` took that for a window from the first line.
- **Self-tests** of what a green row does not show: nothing a window
expects is logged outside it there, a base row has no window, and a row
turns red on the order of `disturb` only when a handshake record lands
where the order moved. `docker-convergence` runs both in every row,
before it downloads the image.
- `selftest-replication-errors.sh`: `replication_errors` on 20 synthetic
errors logs, through a `docker` stub, so that `mark_logs`,
`window_open`, `window_close` and `since_mark` read them as they read a
container's.
- `selftest-disturb-restart-ds.sh`: `disturb` and `settle` against stubs
that record their calls and move the clock. The window opens before the
restart and closes 10 s after the server serves again, and
`disturbances.txt` ends the restart when the server served, not after
the grace.
- **Summary** (`collect.sh`): a row with what was disturbed, when, and
how long it took to serve again (`disturbances.txt`), or that the
disturbance did not complete, or did not start because the run ended
before the load; the handshakes a window expected.
## CI
`docker-convergence` gets the matrix axis `disturbance: [none,
restart-ds]`, four rows, each on a runner of its own:
| row | load | artifact |
|---|---|---|
| `rs534, none` | 1800 s | `convergence-rs534` (as before) |
| `combined, none` | 1800 s | `convergence-combined` (as before) |
| `rs534, restart-ds` | 900 s | `convergence-rs534-restart-ds` |
| `combined, restart-ds` | 900 s | `convergence-combined-restart-ds` |
A disturbed row runs half the load of a base one: what it is after
happens around the disturbance, and it holds one of the runners the
organization shares. Each row runs the two self-tests first, in seconds
and without Docker. A red row of either kind turns the Build run red and
skips the deploy of a push to master, as a base row does. The job names
change (`docker-convergence (rs534, none)` and so on); master has no
required status checks. The comment of the job that `rs534` and
`combined` fail until #1206, #1215 and #1195 are fixed goes: all three
are, and both rows were green on the last three Build runs of master.
## Testing
CI of the fourth round, run
[40544021845](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/40544021845)
(at ead0e02): every job green, 24 of 24.
| row | restart until serving | second segment | converged after the
load | result |
|---|---|---|---|---|
| `rs534, restart-ds` | 131 s | 453 s | 260 s | green, no record
expected |
| `combined, restart-ds` | 225 s | 350 s | 884 s | green, one record
expected: 178 on `cv-c0`, 31 s before the window closed |
Neither restart lost a change: `ldifdiff`, `verify-index` and the
changelogs were green, the changes of each restarted server without a
gap, as in every restart-ds row of the rounds before that got to the
checks. In the restart-ds rows of rounds 2 to 4 only the restarted
directory server reconnected (`reconnections.txt`).
The rounds before:
- **Round 5**, run
[40653842203](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/40653842203)
(at 53444f2): cancelled by the push of the sixth round before the
convergence rows ran.
- **Round 3**, run
[40463887505](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/40463887505)
(at a1d1944): `combined, restart-ds` failed on 145 at ERROR on `cv-c2`,
within the window, on the connection of the restarted `cv-c1`. The
fourth round expects 145 within a window.
- **Round 2**, run
[39909337627](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/39909337627)
(at 249e520): both `restart-ds` rows failed on one record each, 119 at
WARNING on the restarted `cv-d1` in `rs534`, 178 at ERROR on `cv-c0` in
`combined`. The third round expects them within the window of a restart.
- **Round 1**, run
[39834888428](https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/39834888428)
(at 0863114): `combined, restart-ds` waited for the health of the
restarted container, which a probe that did not get through its 30 s on
the loaded runner held back 7 minutes after the server served. The
second round waits for the start instead, and showed that a restart
leaves no gap in the changelog.
- The base rows were green in the runs of rounds 1 to 4.
Locally, rounds 5 and 6:
- `selftest-replication-errors.sh`: 20 of 20 with the awk of macOS and
with mawk (`debian:bookworm-slim`). Against 21 mutants of
`assert-converged.sh` it fails on 19:
- the window bounds dropped or off by one, the first line or the mark
off by one;
- 145 or 179 out of the list, the space after the msgID dropped, or the
msgID anchor loosened to `.*(145|178|179) `;
- the WARNING clause dropped, or widened in severity, in category or to
any `SSLHandshakeException`;
- `bad_certificate` out of the first filter, the loop over the windows
off, `window_close` writing the wrong count.
The two that survive widen the clause of 145/178/179 to any severity or
any category. No record that gets past the first filter tells them
apart: outside SYNC at ERROR it gets past only with
`SSLHandshakeException` or `bad_certificate` in it, which those messages
do not carry.
- `selftest-disturb-restart-ds.sh`: passes with the bash of macOS and
with bash 5 (`debian:bookworm-slim`), and fails on 14 mutants of
`disturb-restart-ds.sh`:
- the grace dropped, the window closed before it or not at all;
- the window opened after the restart, or the stamp of serving taken
after the grace;
- `-t 120` dropped;
- the start of the restart taken after it, or the wrong start handed to
`started_since`;
- another timeout, the first directory server restarted, the stamp in
seconds;
- `settle` waiting on another server or with another timeout.
- `disturb` against a stubbed `docker` (round 5): a 145 logged 5 s into
the grace goes to `.expected`.
- `errors_lines` against a `debian:bookworm-slim` container without the
errors log, in a shell with `set -eE -o pipefail` as `run.sh` runs them.
With `cat … | wc -l`, `mark_logs`, `window_open` and `window_close` went
on, `window_open` writing 0. With the redirect, each stopped the shell
with 2, and with a log of 3 lines there it counts 3.
- `summarize`: "not started" with no `LOAD_START_MS`, "not completed"
with one and no `disturbances.txt`, the restart with it, no row without
a disturbance.
- `lib.sh`: no `DISTURBANCE` gives 120 s of load,
`DISTURBANCE=restart-ds` 900 s with `DISTURB_AT=300`, and a `DURATION`
that is set wins.
- `bash -n` of every script; `build.yml` parses, with the matrix, the
`DURATION` expression, the artifact names as above and the self-tests as
the first step after the checkout.
- Not run end to end locally: the Docker VM here (4 CPU, 3.8 GB) brings
`rs534` up in no less than 2400 s, and `combined` stalls under the load
before the checks.
The branch is on master `cba3c0f461` again.