Diagnostics for intermittent CI failures

.github/workflows/dnsbl.yml

@@ -0,0 +1,22 @@
+name: dnsbl loop
+
+on:
+  pull_request:
+    branches: master
+
+jobs:
+  # Repeat the Spamhaus DBL sender check until it is refused or the iterations run out
+  test:
+    runs-on: ubuntu-latest
+
+    steps:
+      - name: Checkout repository and submodules
+        uses: actions/checkout@v3
+        with:
+          submodules: recursive
+
+      - name: Build docker image
+        run: make build-no-cache
+
+      - name: Run the loop
+        run: make dnsbl

Makefile

@@ -14,6 +14,20 @@ WAIT_TIMEOUT = 300
 TEST_DNS ?=
 DNS_FLAG = $(if $(TEST_DNS),--dns $(TEST_DNS),)
 
+# Log which resolver the container uses and what dbl.spamhaus.org answers it,
+# before any mail is sent (see test/share/tests/dnsbl-probe.sh). reverse and
+# ldap2 inherit the host resolver, so the answer depends on where the suite
+# runs; without this a refused resolver shows up only as unexplained delivery
+# failures, and a run that passed says nothing about the blocklist at all.
+define dnsbl_probe
+	-@docker exec $(1) sh /tmp/tests/dnsbl-probe.sh
+endef
+
+# The dnsbl suite repeats the sender check that fails when a resolver is
+# refused; see test/dnsbl-loop.sh for the cost per iteration.
+DNSBL_ITERATIONS ?= 20
+DNSBL_INTERVAL ?= 15
+
 all: build-no-cache default reverse ldap ldap2 sieve ecdsa traefik_acmev1 traefik_acmev2 clean
 no-build: default reverse ldap ldap2 sieve ecdsa traefik_acmev1 traefik_acmev2 clean
 default: init_default fixtures_default run_default stop_default
@@ -24,6 +38,7 @@ sieve: init_sieve fixtures_sieve run_sieve stop_sieve
 ecdsa: init_ecdsa run_ecdsa stop_ecdsa
 traefik_acmev1: init_traefik_acmev1 run_traefik_acmev1 stop_traefik_acmev1
 traefik_acmev2: init_traefik_acmev2 run_traefik_acmev2 stop_traefik_acmev2
+dnsbl: init_dnsbl run_dnsbl stop_dnsbl
 
 build-no-cache:
 	docker build --no-cache -t $(NAME) .
@@ -232,6 +247,7 @@ fixtures_ldap2:
 	docker exec mailserver_ldap2 /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 11332 ; do sleep 1 ; done"  # rspamd
 	docker exec mailserver_ldap2 /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 993 ; do sleep 1 ; done"  # dovecot imaps
 	docker exec mailserver_ldap2 /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 587 ; do sleep 1 ; done"  # submission
+	$(call dnsbl_probe,mailserver_ldap2)
 	docker exec mailserver_ldap2 /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-existing-user.txt"
 	docker exec mailserver_ldap2 /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-valid-user-subaddress.txt"
 	docker exec mailserver_ldap2 /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-non-existing-user.txt"
@@ -321,6 +337,7 @@ fixtures_reverse:
 	docker exec mailserver_reverse /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 11332 ; do sleep 1 ; done"  # rspamd
 	docker exec mailserver_reverse /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 993 ; do sleep 1 ; done"  # dovecot imaps
 	docker exec mailserver_reverse /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 587 ; do sleep 1 ; done"  # submission
+	$(call dnsbl_probe,mailserver_reverse)
 	docker exec mailserver_reverse /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-existing-user.txt"
 	docker exec mailserver_reverse /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-valid-user-subaddress-with-default-separator.txt"
 	docker exec mailserver_reverse /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-non-existing-user.txt"
@@ -414,6 +431,36 @@ stop_traefik_acmev2:
 	-docker rm -f \
 		mailserver_traefik_acmev2 || true
 
+init_dnsbl: init_redis init_mariadb
+	-docker rm -f \
+		mailserver_dnsbl || true
+
+	docker run \
+		-d \
+		--name mailserver_dnsbl \
+		--link mariadb:mariadb \
+		--link redis:redis \
+		$(DNS_FLAG) \
+		-e DBPASS=testpasswd \
+		-e RSPAMD_PASSWORD=testpasswd \
+		-e VMAILUID=`id -u` \
+		-e VMAILGID=`id -g` \
+		-e DISABLE_CLAMAV=true \
+		-e DISABLE_DNS_RESOLVER=true \
+		-e TESTING=true \
+		-v "`pwd`/test/share/tests":/tmp/tests \
+		-v "`pwd`/test/share/ssl/rsa":/var/mail/ssl \
+		-h mail.domain.tld \
+		-t $(NAME)
+
+run_dnsbl:
+	docker exec mailserver_dnsbl /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 25 ; do sleep 1 ; done"
+	docker exec mailserver_dnsbl /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 11332 ; do sleep 1 ; done"  # rspamd
+	./test/dnsbl-loop.sh mailserver_dnsbl $(DNSBL_ITERATIONS) $(DNSBL_INTERVAL)
+stop_dnsbl:
+	-docker rm -f \
+		mailserver_dnsbl || true
+
 fixtures_default:
 
 	# Wait for clamav unofficial sigs database update (default)
@@ -423,6 +470,7 @@ fixtures_default:
 	# Wait for rspamd to start (default)
 	docker exec mailserver_default /bin/sh -c "while ! echo PING | nc -z 0.0.0.0 11332 ; do sleep 1 ; done"
 
+	$(call dnsbl_probe,mailserver_default)
 	docker exec mailserver_default /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-existing-user.txt"
 	docker exec mailserver_default /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-existing-user-spam-learning.txt"
 	docker exec mailserver_default /bin/sh -c "python3 /tmp/tests/smtp-send.py 0.0.0.0 25 /tmp/tests/email-templates/external-to-valid-user-subaddress.txt"

test/dnsbl-loop.sh

@@ -0,0 +1,43 @@
+#!/bin/sh
+# Exercise the dbl.spamhaus.org sender check repeatedly, logging the resolver
+# and the blocklist's answers before every attempt, until an attempt is
+# refused or the iterations run out. Both outcomes are logged.
+#
+#   dnsbl-loop.sh <container> <iterations> <interval-seconds>
+#
+# Each iteration costs Spamhaus 9 queries (8 from the probe, 1 from postfix),
+# so the default 20 iterations are 180 queries per run, spaced 15 s apart:
+# a small fraction of what one quiet mail server sends in a day. The interval
+# is longer than the 10 s negative TTL observed on the sender-domain answer,
+# so each attempt reaches Spamhaus rather than the resolver's cache. If the
+# blocklist ever answers 127.255.255.255 ("excessive number of queries") the
+# loop stops at once.
+set -u
+container=$1; iterations=$2; interval=$3
+template=/tmp/tests/email-templates/external-to-existing-user.txt   # MAIL FROM user@gmail.com
+
+i=1
+while [ "$i" -le "$iterations" ]; do
+  echo "[dnsbl-loop] iteration $i/$iterations at $(date -u +%Y-%m-%dT%H:%M:%SZ)"
+  probe=$(docker exec "$container" sh /tmp/tests/dnsbl-probe.sh)
+  printf '%s\n' "$probe"
+  if printf '%s\n' "$probe" | grep -q '127\.255\.255\.255'; then
+    echo "[dnsbl-loop] STOP: Spamhaus answered 127.255.255.255 (excessive number of queries); not continuing"
+    exit 2
+  fi
+  reply=$(docker exec "$container" python3 /tmp/tests/smtp-send.py 0.0.0.0 25 "$template" 2>&1)
+  if printf '%s\n' "$reply" | grep -q 'blocked using dbl'; then
+    echo "[dnsbl-loop] REFUSED at iteration $i:"
+    printf '%s\n' "$reply" | grep 'blocked using dbl' | sed 's/^/    /'
+    exit 1
+  elif printf '%s\n' "$reply" | grep -q '250 2.0.0 Ok: queued'; then
+    echo "[dnsbl-loop] accepted: $(printf '%s\n' "$reply" | grep '250 2.0.0 Ok: queued' | head -1)"
+  else
+    echo "[dnsbl-loop] UNEXPECTED reply at iteration $i:"
+    printf '%s\n' "$reply" | grep '^S:' | sed 's/^/    /'
+    exit 1
+  fi
+  [ "$i" -lt "$iterations" ] && sleep "$interval"
+  i=$((i + 1))
+done
+echo "[dnsbl-loop] $iterations iterations, all accepted"

test/share/tests/dnsbl-probe.sh

@@ -0,0 +1,30 @@
+#!/bin/sh
+# Print what this container's resolver answers for dbl.spamhaus.org, and which
+# resolver that is. Runs inside the mailserver container (needs dig).
+#
+#   dbltest.com -> 127.0.1.2      the permanent test listing: the blocklist works
+#   dbltest.com -> 127.255.255.x  this resolver is refused: every sender gets rejected
+#   dbltest.com -> (nothing)      answered nothing: the blocklist is inert
+#   gmail.com   -> (nothing)      the fixtures' sender domain, the name postfix looks up
+#   example.com -> (nothing)      expected, it is not listed
+#
+# The resolver line gives the nameserver the container is configured with and
+# the resolver's egress address as seen by two whoami services, because a
+# healthy Spamhaus answer does not name it (only a refusal does). ttl is the
+# remaining TTL: a full value is a fresh answer, a lower one came from cache.
+
+q() { dig +time=3 +tries=1 "$@" 2>/dev/null | grep -v '^;'; }
+
+ns=$(awk '/^nameserver/{print $2; exit}' /etc/resolv.conf)
+ak=$(q +short A whoami.akamai.net | head -1)
+gg=$(q +short TXT o-o.myaddr.l.google.com | grep -v edns0 | head -1 | tr -d '"')
+printf '[dnsbl] resolver: nameserver=%s egress-seen-by-akamai=%s egress-seen-by-google=%s\n' "${ns:--}" "${ak:--}" "${gg:--}"
+
+for name in dbltest.com.dbl.spamhaus.org gmail.com.dbl.spamhaus.org example.com.dbl.spamhaus.org; do
+  out=$(dig +time=3 +tries=1 +noall +comments +answer +authority A "$name" 2>&1)
+  st=$(printf '%s\n' "$out" | sed -n 's/.*status: \([A-Z]*\).*/\1/p' | head -1); [ -z "$st" ] && st=unreachable
+  a=$(printf '%s\n' "$out" | grep '[[:space:]]A[[:space:]]' | sed 's/.*[[:space:]]//' | tr '\n' ',' | sed 's/,$//'); [ -z "$a" ] && a=-
+  ttl=$(printf '%s\n' "$out" | grep -v '^;' | awk 'NF>=5{print $2; exit}'); [ -z "$ttl" ] && ttl=-
+  t=$(q +short TXT "$name" | grep '^"' | head -1); [ -z "$t" ] && t=-
+  printf '[dnsbl] %-32s status=%-11s A=%-16s ttl=%-5s %s\n' "$name" "$st" "$a" "$ttl" "$t"
+done