From 3d02d8156223a8ba80800f80bf0a2e7426b883c8 Mon Sep 17 00:00:00 2001 From: Jose Diaz-Gonzalez Date: Sun, 9 Aug 2026 02:22:13 -0400 Subject: [PATCH] fix: stop logs tests leaking a global app-label-alias The `app-label-alias` test left the global property set, so every later test in the file generated a vector source filtering on a label that dokku never applies to a container, silently collecting nothing. Clearing it in teardown restores log collection for the rest of the file. The cron routing test now asserts against console sinks rather than files, since the sink an event reached is identifiable from vector's own output without depending on a writable host mount, and its task sleeps either side of its output because a cron container that exits immediately is removed before vector can attach to it. --- tests/apps/python/cron_task.py | 16 ++++++++ tests/unit/logs.bats | 75 ++++++++++++++++++---------------- 2 files changed, 55 insertions(+), 36 deletions(-) create mode 100644 tests/apps/python/cron_task.py diff --git a/tests/apps/python/cron_task.py b/tests/apps/python/cron_task.py new file mode 100644 index 000000000..037c56b95 --- /dev/null +++ b/tests/apps/python/cron_task.py @@ -0,0 +1,16 @@ +import sys +import time + + +def main(args): + # a log shipper attaches to a container after it receives the start event, + # and a cron container is removed the moment it exits. sleep on either side + # of the output so that the shipper has time to attach before the line is + # written and time to read it before the container is gone. + time.sleep(5) + print(' '.join(args[1:]), flush=True) + time.sleep(3) + + +if __name__ == '__main__': + main(sys.argv) diff --git a/tests/unit/logs.bats b/tests/unit/logs.bats index 4075a95d1..e04885a2a 100644 --- a/tests/unit/logs.bats +++ b/tests/unit/logs.bats @@ -9,6 +9,10 @@ setup() { teardown() { destroy_app + # a leftover app-label-alias makes every later test's vector source filter on + # a label that dokku never applies to a container, which silently disables log + # collection for the rest of the file + dokku logs:set --global app-label-alias >/dev/null 2>/dev/null || true dokku logs:set --global vector-image >/dev/null 2>/dev/null || true dokku logs:set --global vector-networks >/dev/null 2>/dev/null || true dokku logs:set --global vector-sink >/dev/null 2>/dev/null || true @@ -1180,7 +1184,7 @@ teardown() { assert_output "true" } -@test "(logs) vector-cron-sink ships cron task output to a file sink" { +@test "(logs) vector-cron-sink routes cron task output to the cron sink" { run deploy_app python dokku@$DOKKU_DOMAIN:$TEST_APP template_cron_file_marker echo "output: $output" echo "status: $status" @@ -1194,20 +1198,16 @@ teardown() { echo "status: $status" assert_success - # a file sink silently writes nothing if the container cannot write to the - # dokku-owned mount, so fail loudly rather than time out below - run /bin/bash -c "docker exec vector-vector-1 id -u" - echo "output: $output" - echo "status: $status" - assert_success - assert_output "0" - - run /bin/bash -c "dokku logs:set $TEST_APP vector-sink 'file://?path=/var/log/dokku/apps/$TEST_APP/app.log&encoding[codec]=text&idle_timeout_secs=1'" + # both sinks write to vector's own stdout, with different codecs, so the sink + # an event was routed to is identifiable without depending on a writable + # mount: the cron branch emits json carrying the fields the remap adds, while + # anything reaching the plain sink emits the bare message + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink 'console://?encoding[codec]=text'" echo "output: $output" echo "status: $status" assert_success - run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink 'file://?path=/var/log/dokku/apps/$TEST_APP/cron-{{ dokku_cron_id }}.log&encoding[codec]=text&idle_timeout_secs=1'" + run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink 'console://?encoding[codec]=json'" echo "output: $output" echo "status: $status" assert_success @@ -1223,16 +1223,15 @@ teardown() { echo "status: $status" assert_success - run wait_for_log_marker "/var/log/dokku/apps/$TEST_APP/cron-$cron_id.log" VECTOR_CRON_OK + run wait_for_vector_cron_event VECTOR_CRON_OK "$cron_id" echo "output: $output" echo "status: $status" dump_vector_diagnostics "$TEST_APP" assert_success - # the cron branch is routed away from the plain sink, so the marker must not - # also land in the app log. a marker here instead means the route condition - # failed to match rather than that nothing was collected - run count_log_marker "/var/log/dokku/apps/$TEST_APP/app.log" VECTOR_CRON_OK + # a bare message line would mean the event reached the plain sink instead of + # being routed onto the cron branch + run count_vector_plain_lines VECTOR_CRON_OK echo "output: $output" echo "status: $status" assert_output "0" @@ -1257,48 +1256,49 @@ wait_for_vector_route() { return 1 } -wait_for_log_marker() { - declare desc="waits for a marker to be flushed to a vector file sink" - declare LOGFILE="$1" MARKER="$2" +wait_for_vector_cron_event() { + declare desc="waits for a marker to arrive on the cron branch, carrying the fields the remap adds" + declare MARKER="$1" CRON_ID="$2" local i for i in $(seq 1 60); do - if grep -q "$MARKER" "$LOGFILE" 2>/dev/null; then + if docker logs vector-vector-1 2>/dev/null | grep "$MARKER" | + jq -e --arg id "$CRON_ID" 'select(.dokku_cron_id == $id)' >/dev/null 2>/dev/null; then return 0 fi sleep 1 done - echo "timed out waiting for $MARKER in $LOGFILE" + echo "timed out waiting for a cron-routed $MARKER event with dokku_cron_id=$CRON_ID" return 1 } -count_log_marker() { - declare desc="counts marker occurrences, treating a missing log file as zero" - declare LOGFILE="$1" MARKER="$2" +count_vector_plain_lines() { + declare desc="counts bare message lines, which only the text-encoded plain sink emits" + declare MARKER="$1" - if [[ ! -f "$LOGFILE" ]]; then - echo "0" - return 0 - fi - - grep -c "$MARKER" "$LOGFILE" || true + docker logs vector-vector-1 2>/dev/null | grep -c -x "$MARKER" || true } dump_vector_diagnostics() { declare desc="prints the state needed to tell apart the ways cron shipping can fail" declare APP="$1" - echo "--- sink files written ---" - ls -la "/var/log/dokku/apps/$APP/" || echo "no sink directory was created" + # sources matter as much as routing here: a stale app-label-alias makes the + # source filter on a label no container carries, which collects nothing + echo "--- generated config ---" + jq '{sources, transforms, sinks}' /var/lib/dokku/data/logs/vector.json || true - echo "--- generated routing ---" - jq '{transforms, sinks}' /var/lib/dokku/data/logs/vector.json || true + echo "--- containers carrying the app label ---" + docker ps --all --filter "label=com.dokku.app-name=$APP" --format '{{.Names}} {{.Status}}' || true + + echo "--- vector stdout, where both sinks write ---" + docker logs vector-vector-1 2>/dev/null | tail -20 || true # vector reports template_failed and other component errors on stderr, so # keep it separate from the collected log lines on stdout echo "--- vector stderr ---" - docker logs vector-vector-1 2>&1 1>/dev/null | tail -30 || true + docker logs vector-vector-1 2>&1 1>/dev/null | tail -20 || true } template_cron_file_marker() { @@ -1306,11 +1306,14 @@ template_cron_file_marker() { local APP="$1" APP_REPO_DIR="$2" [[ -z "$APP" ]] && local APP="$TEST_APP" echo "injecting cron app.json -> $APP_REPO_DIR/app.json" + # cron_task.py sleeps either side of its output. a task that exits + # immediately is removed before vector can attach to it, which is documented + # behavior rather than something this test should assert against cat <"$APP_REPO_DIR/app.json" { "cron": [ { - "command": "echo VECTOR_CRON_OK", + "command": "python3 cron_task.py VECTOR_CRON_OK", "schedule": "@daily" } ]