From f1e2ab125344f277819aebb3114c098cf14f90ec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marcos=20M=C3=A9ndez?= Date: Mon, 28 Sep 2026 01:44:39 +0000 Subject: [PATCH] Read an INFO reply the way Redis writes it, and print the log when it fails The first build of this component died in its own conf script, with a message that said no Redis answered INFO on [::1]:6379 after 30 tries. The server was up, listening on both loopback families, and answering. Redis speaks CRLF. Every line of an INFO reply ends "\r\n", redis-cli prints the reply as it came, and the check was anchored with a dollar: redis-cli INFO server | grep tcp_port | od -c t c p _ p o r t : 6 3 7 9 \r \n grep -q "^tcp_port:6379$" no match tr -d '\r' | grep -qx "tcp_port:6379" match Measured in the chroot of the failed build, which is also where the fix was proved before this commit was written. The reply now goes through tr in one function that both the wait and the per address check call, and the stub in tests/conf.bats answers in CRLF, so every test in that file covers the real shape rather than a convenient one. One test says so by name and asserts both halves: that the dollar anchored form does not match, and that the form this script uses does. Two things the same failure showed about the script rather than about Redis. The log went with the directory. The check runs the server in a scratch directory and removes it on the way out, which took the server's own log with it, so the build that failed could not be diagnosed from its own output: the log had to be reproduced by hand in the tree fab left behind. The fatal path prints its last twenty lines first now. And the message was wrong in a way that sent the reading in the wrong direction. "after 30 tries" belonged to the wait on [::1]; the check that actually failed had made one attempt against one address. The two facts are printed as two facts. Nothing the image gets changes. Coverage stays at 100 percent on all three measured files, 126 lines, 67 bats tests. --- .github/workflows/tests.yml | 4 +-- COVERAGE.md | 17 ++++++++---- changelog | 29 +++++++++++++++++++++ conf | 38 ++++++++++++++++++++++----- tests/conf.bats | 52 +++++++++++++++++++++++++++++++++---- version | 2 +- 6 files changed, 123 insertions(+), 19 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index f7fa801..cfadc07 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -19,8 +19,8 @@ permissions: jobs: tests: - # COVERAGE.md: the conf script at 100 percent (36/36), the first boot - # hook at 100 (31/31) and its library at 100 (56/56), 65 bats tests. The + # COVERAGE.md: the conf script at 100 percent (39/39), the first boot + # hook at 100 (31/31) and its library at 100 (56/56), 67 bats tests. The # threshold is the measured number and is only ever raised (decision # 0006). This job produces the check # "tests / coverage", the required status on main; the job id is part of diff --git a/COVERAGE.md b/COVERAGE.md index 1a61837..4a9bcc4 100644 --- a/COVERAGE.md +++ b/COVERAGE.md @@ -12,12 +12,12 @@ repository does not carry a boot test of its own. | --- | --- | --- | --- | | overlay/usr/lib/inithooks/lib/redis.sh | tests/redis.bats (20 tests) | 100 percent (56/56) under kcov | every function and every branch | | overlay/usr/lib/inithooks/firstboot.d/35redispass | tests/hook.bats (18 tests) | 100 percent (31/31) under kcov | every path, including the four failures that matter | -| conf | tests/conf.bats (15 tests) | 100 percent (36/36) under kcov | the include appended once and last, the fragments, the running server on both families, and every refusal | +| conf | tests/conf.bats (17 tests) | 100 percent (39/39) under kcov | the include appended once and last, the fragments, the running server on both families, every refusal, the CRLF an INFO reply really carries, and the server log a failure prints | | overlay/etc/redis/redis.conf.d/\* | tests/conf.bats (2 tests) | not executable | asserted as content: two literal bind addresses and no name, the default account restricted to `+info`, the administrative account published `off`, and no `requirepass` anywhere | | overlay/usr/lib/inithooks/bin/redispass.py | none | 0 | dialog wrapper, only reached with a terminal attached | -Total over the three measured shell files: **100 percent (123/123)**, -65 bats tests over four files (conf, hook, library, unit shape). +Total over the three measured shell files: **100 percent (126/126)**, +67 bats tests over four files (conf, hook, library, unit shape). `tests/coverage.sh` fails below `COVERAGE_THRESHOLD`, which the workflow sets to 100, the measured number. It is only ever raised (decision 0006). @@ -25,7 +25,7 @@ to 100, the measured number. It is only ever raised (decision 0006). kcov line coverage (threshold 100 percent): 100.00 56/56 redis.sh 100.00 31/31 35redispass - 100.00 36/36 conf + 100.00 39/39 conf ## What the tests are really about @@ -47,12 +47,19 @@ require it absent, and the file's mode is asserted to be 0640. The upstream appliance wrote `requirepass` into a file the package ships world readable, which is the defect this replaces. -Under all three, one Redis behaviour that every check is shaped around: +Under all three, two Redis behaviours that every check is shaped around. + **redis-cli exits 0 when the server answers with an error.** One test drives the hook with a wrong password through a stub that exits 0 and prints `WRONGPASS`, and requires the hook to fail anyway. A check written on `$?` would have passed. +**Redis speaks CRLF.** Every line of an `INFO` reply ends `\r\n`, and +redis-cli prints the reply as it came, so a grep anchored with `$` never +matches a whole line. The first build of this component died there. Every +`INFO` stub in `tests/conf.bats` answers in CRLF now, so the whole file +covers it, and one test says so by name. + ## What is not measured, and what would change that `overlay/usr/lib/inithooks/bin/redispass.py` is a Dialog wrapper, reached diff --git a/changelog b/changelog index f1fc675..4c5d647 100644 --- a/changelog +++ b/changelog @@ -1,3 +1,32 @@ +unit-redis-1.0.1 (1) keel; urgency=low + + * Read an INFO reply the way Redis writes it. Redis speaks CRLF: every + line of an INFO reply ends "\r\n" and redis-cli prints the reply as it + came, so "tcp_port:6379" is really "tcp_port:6379\r" and the conf + script's check, anchored with a dollar, never matched it. The first + build of this component died there, with a server that was up and + listening on both families and a message that said no Redis answered. + Measured in the chroot of that build: + + redis-cli INFO server | grep tcp_port | od -c + t c p _ p o r t : 6 3 7 9 \r \n + + The reply now goes through tr before it is read, in one function both + checks call, and the stub in tests/conf.bats answers in CRLF so every + test in that file covers it. + + * A failure prints the server's own log. The check removes the directory + it runs the server in, so the log that explains a failure went with it + and the build that failed could not be diagnosed from its own output. + The fatal path now prints the last twenty lines first. + + * The message that failure prints says which address reported nothing and + how long the wait was, as two separate facts. The old one read "no Redis + answered INFO on [127.0.0.1]:6379 after 30 tries" for a check that had + made one attempt, because the tries belong to the wait on [::1]. + + -- Keel Linux maintainers Mon, 28 Sep 2026 01:45:00 +0000 + unit-redis-1.0.0 (1) keel; urgency=low * The Redis component, as a fab unit (decision 0010): a plan, an overlay diff --git a/conf b/conf index c48baff..4d92120 100755 --- a/conf +++ b/conf @@ -44,9 +44,37 @@ REDIS_TRIES="${REDIS_TRIES:-30}" fatal() { echo "FATAL [unit-redis conf]: $*" >&2 + # The server's own log, when there is one, because the check below + # removes the directory it is in and a build that failed for want of a + # log is a build nobody can diagnose. The first build of this component + # failed exactly that way. + if [ -s "$REDIS_CHECK_DIR/redis.log" ]; then + echo "FATAL [unit-redis conf]: the last lines of the server's own log:" >&2 + tail -n 20 "$REDIS_CHECK_DIR/redis.log" >&2 + fi exit 1 } +# redis_port_line HOST: the tcp_port line the server at HOST reports, with +# the carriage returns taken out, and nothing when it reports none. +# +# The tr is the whole point of this function. Redis speaks CRLF: every line +# of an INFO reply ends "\r\n", and redis-cli prints the reply as it came, +# so "tcp_port:6379" is really "tcp_port:6379\r" and a grep anchored with a +# dollar never matches it. The first build of this component failed there, +# with a server that was up and listening on both families and a check that +# said no Redis answered. Measured in the chroot of that build: +# +# redis-cli INFO server | grep tcp_port | od -c +# t c p _ p o r t : 6 3 7 9 \r \n +# +# Anything that reads an INFO reply has to do this, or match a prefix and +# never a whole line. +redis_port_line() { + redis-cli -h "$1" -p "$REDIS_PORT" INFO server 2>/dev/null \ + | tr -d '\r' | grep -x "tcp_port:$REDIS_PORT" +} + # 1. The fragments. They come from the overlay, which fab applied before # this script ran, so their absence means the overlay did not arrive. [ -d "$REDIS_CONF_D" ] || fatal "$REDIS_CONF_D is not in the tree: the component overlay did not arrive" @@ -94,9 +122,7 @@ trap stop_server EXIT INT TERM attempt=1 while [ "$attempt" -le "$REDIS_TRIES" ]; do - if redis-cli -h ::1 -p "$REDIS_PORT" INFO server 2>/dev/null | grep -q '^redis_version:'; then - break - fi + redis_port_line ::1 > /dev/null && break attempt=$((attempt + 1)) sleep 1 done @@ -109,9 +135,9 @@ done # after 20-keel-acl.conf, and because it is exactly what `keel inspect` runs # to read this machine's database.server.role. for host in $REDIS_CHECK_HOSTS; do - redis-cli -h "$host" -p "$REDIS_PORT" INFO server 2>/dev/null \ - | grep -q "^tcp_port:$REDIS_PORT\$" \ - || fatal "no Redis answered INFO on [$host]:$REDIS_PORT after $REDIS_TRIES tries" + redis_port_line "$host" > /dev/null \ + || fatal "no Redis reported tcp_port:$REDIS_PORT on [$host]:$REDIS_PORT," \ + "after $REDIS_TRIES tries on [::1]" done # And the other half of 20-keel-acl.conf: a client with no secret is refused diff --git a/tests/conf.bats b/tests/conf.bats index 82d1fed..16f1e06 100644 --- a/tests/conf.bats +++ b/tests/conf.bats @@ -43,9 +43,14 @@ while [ $# -gt 0 ]; do done if [ -n "$pidfile" ]; then sleep 60 & echo $! > "$pidfile"; echo "started-pid $!" >> "$CALLS"; fi exit 0' + # The stub answers the way a real server does, which here means CRLF: + # every line of an INFO reply ends "\r\n" and redis-cli prints the + # reply as it came. The first build of this component failed because + # the check was anchored with a dollar and the stub of the day was not + # faithful about it, so this is the shape every INFO stub below has. stub redis-cli 'echo "redis-cli $*" >> "$CALLS" case " $* " in - *" INFO server "*|*" INFO server") printf "redis_version:8.0.2\ntcp_port:6379\n" ;; + *" INFO server "*|*" INFO server") printf "# Server\r\nredis_version:8.0.2\r\ntcp_port:6379\r\n" ;; *" GET "*) echo "NOPERM User default has no permissions to run the '"'"'get'"'"' command" ;; esac exit 0' @@ -134,20 +139,57 @@ run_conf() { export REDIS_TRIES=2 run_conf [ "$status" -eq 1 ] - [[ "$output" == *"no Redis answered INFO on [::1]:6379 after 2 tries"* ]] + [[ "$output" == *"no Redis reported tcp_port:6379 on [::1]:6379"* ]] + [[ "$output" == *"after 2 tries on [::1]"* ]] } @test "a server on one family only fails, which is the trap this exists for" { stub redis-cli 'echo "redis-cli $*" >> "$CALLS" case " $* " in - *" -h ::1 "*" INFO server"*) printf "redis_version:8.0.2\ntcp_port:6379\n" ;; + *" -h ::1 "*" INFO server"*) printf "# Server\r\ntcp_port:6379\r\n" ;; *" -h 127.0.0.1 "*) exit 1 ;; esac exit 0' export REDIS_TRIES=1 run_conf [ "$status" -eq 1 ] - [[ "$output" == *"no Redis answered INFO on [127.0.0.1]:6379"* ]] + [[ "$output" == *"no Redis reported tcp_port:6379 on [127.0.0.1]:6379"* ]] +} + +@test "an INFO reply in CRLF is read, which a dollar anchor would not have" { + # The defect the first build of this component died on. redis-cli + # prints the reply as it came and Redis speaks CRLF, so the line is + # "tcp_port:6379\r"; a check anchored with a dollar never matched it, + # and the message said no Redis answered while the server was up and + # listening on both families. Measured in the chroot of that build with + # od -c. The stub above is CRLF for the same reason, so every test in + # this file covers it; this one says so by name. + run bash -c 'printf "# Server\r\ntcp_port:6379\r\n" | grep -q "^tcp_port:6379$"' + [ "$status" -ne 0 ] + run bash -c 'printf "# Server\r\ntcp_port:6379\r\n" | tr -d "\r" | grep -qx "tcp_port:6379"' + [ "$status" -eq 0 ] + run_conf + [ "$status" -eq 0 ] +} + +@test "a failure carries the server's own log, which the check then removes" { + stub redis-server 'echo "redis-server $*" >> "$CALLS" +pidfile=""; logfile="" +while [ $# -gt 0 ]; do + if [ "$1" = --pidfile ]; then pidfile=$2; fi + if [ "$1" = --logfile ]; then logfile=$2; fi + shift +done +[ -n "$logfile" ] && echo "1:M Ready to accept connections tcp" > "$logfile" +if [ -n "$pidfile" ]; then sleep 60 & echo $! > "$pidfile"; echo "started-pid $!" >> "$CALLS"; fi +exit 0' + stub redis-cli 'exit 1' + export REDIS_TRIES=1 + run_conf + [ "$status" -eq 1 ] + [[ "$output" == *"the last lines of the server's own log"* ]] + [[ "$output" == *"Ready to accept connections tcp"* ]] + [ ! -e "$REDIS_CHECK_DIR" ] } @test "redis-server refusing the file fails the build" { @@ -160,7 +202,7 @@ exit 0' @test "a server that hands a key to a client with no secret fails the build" { stub redis-cli 'echo "redis-cli $*" >> "$CALLS" case " $* " in - *" INFO server"*) printf "redis_version:8.0.2\ntcp_port:6379\n" ;; + *" INFO server"*) printf "# Server\r\ntcp_port:6379\r\n" ;; *" GET "*) echo "(nil)" ;; esac exit 0' diff --git a/version b/version index 3eefcb9..7dea76e 100644 --- a/version +++ b/version @@ -1 +1 @@ -1.0.0 +1.0.1