diff --git a/docs/deployment/logs.md b/docs/deployment/logs.md index b29ac6e0a..dc507e098 100644 --- a/docs/deployment/logs.md +++ b/docs/deployment/logs.md @@ -256,6 +256,8 @@ As with app-specific sink settings, the global value may also be cleared by sett dokku logs:set --global vector-sink ``` +The generated vector configuration is also rewritten whenever an app is renamed, cloned or destroyed. A renamed app keeps shipping to its sink under the new name, a cloned app gets a source of its own for the sink it inherited, and a destroyed app's source and sink are removed rather than left pointing at an endpoint that was decommissioned with the app. + ##### Log Sink DSN Format The DSN form of a sink is as follows: diff --git a/plugins/logs/functions.go b/plugins/logs/functions.go index 6495eb4c0..8cabde7ab 100644 --- a/plugins/logs/functions.go +++ b/plugins/logs/functions.go @@ -538,6 +538,17 @@ func vectorScopes() []vectorAppSinks { }) } +// regenerateVectorConfig rewrites the generated vector config so that it matches +// the current set of apps and their properties. App lifecycle triggers call this +// instead of writeVectorConfig because the config is derived state: failing to +// rewrite it should not abort the app operation that changed the state it is +// derived from. +func regenerateVectorConfig() { + if err := writeVectorConfig(); err != nil { + common.LogWarn(fmt.Sprintf("Unable to write updated vector config: %s", err.Error())) + } +} + func writeVectorConfig() error { data, err := buildVectorConfig(vectorScopes()) if err != nil { diff --git a/plugins/logs/functions_test.go b/plugins/logs/functions_test.go index a5e1bd61d..122afcac7 100644 --- a/plugins/logs/functions_test.go +++ b/plugins/logs/functions_test.go @@ -2,6 +2,7 @@ package logs import ( "encoding/json" + "fmt" "os" "path/filepath" "strings" @@ -291,6 +292,10 @@ func setupScopesTest(t *testing.T, apps []string) { t.Fatalf("PropertySetup: %v", err) } + if err := common.CreateDataDirectory("logs"); err != nil { + t.Fatalf("CreateDataDirectory: %v", err) + } + for _, appName := range apps { if err := os.MkdirAll(filepath.Join(os.Getenv("DOKKU_ROOT"), appName), 0755); err != nil { t.Fatalf("MkdirAll %s: %v", appName, err) @@ -298,6 +303,141 @@ func setupScopesTest(t *testing.T, apps []string) { } } +// setLogsProperty sets a logs property for the given scope and regenerates the +// config, standing in for the logs:set command +func setLogsProperty(t *testing.T, appName string, property string, value string) { + t.Helper() + + if err := common.PropertyWrite("logs", appName, property, value); err != nil { + t.Fatalf("PropertyWrite %s %s: %v", appName, property, err) + } + + if err := writeVectorConfig(); err != nil { + t.Fatalf("writeVectorConfig: %v", err) + } +} + +// readVectorConfig decodes the generated config from disk +func readVectorConfig(t *testing.T) map[string]interface{} { + t.Helper() + + b, err := os.ReadFile(filepath.Join(common.GetDataDirectory("logs"), "vector.json")) + if err != nil { + t.Fatalf("ReadFile vector.json: %v", err) + } + + var decoded map[string]interface{} + if err := json.Unmarshal(b, &decoded); err != nil { + t.Fatalf("Unmarshal vector.json: %v", err) + } + + return decoded +} + +// assertComponents checks whether an app has a source and a sink in the config +func assertComponents(t *testing.T, decoded map[string]interface{}, appName string, want bool) { + t.Helper() + + components := map[string]string{ + "sources": fmt.Sprintf("docker-source:%s", appName), + "sinks": fmt.Sprintf("docker-sink:%s", appName), + } + + for section, id := range components { + group, ok := lookup(t, decoded, section).(map[string]interface{}) + if !ok { + t.Fatalf("%s is not a map", section) + } + + if _, ok := group[id]; ok != want { + t.Errorf("%s[%q] exists = %v, want %v", section, id, ok, want) + } + } +} + +// TestTriggerPostDeleteRewritesVectorConfig covers a destroyed app leaving its +// source and sink behind forever. post-delete fires before the app root is +// removed, so the app is still listed by UnfilteredDokkuApps at this point and +// only drops out because its properties are destroyed first. +func TestTriggerPostDeleteRewritesVectorConfig(t *testing.T) { + setupScopesTest(t, []string{"appa", "appb"}) + setLogsProperty(t, "appa", "vector-sink", "console://?encoding[codec]=json") + setLogsProperty(t, "appb", "vector-sink", "console://?encoding[codec]=json") + + assertComponents(t, readVectorConfig(t), "appa", true) + + if err := TriggerPostDelete("appa"); err != nil { + t.Fatalf("TriggerPostDelete: %v", err) + } + + decoded := readVectorConfig(t) + assertComponents(t, decoded, "appa", false) + assertComponents(t, decoded, "appb", true) +} + +// TestTriggerPostAppRenameSetupRewritesVectorConfig covers the rename case: the +// sink property follows the app, so without a regeneration the surviving source +// filters on a label no container carries and the new name has no source at all. +func TestTriggerPostAppRenameSetupRewritesVectorConfig(t *testing.T) { + setupScopesTest(t, []string{"appa", "appa-renamed"}) + setLogsProperty(t, "appa", "vector-sink", "console://?encoding[codec]=json") + + if err := TriggerPostAppRenameSetup("appa", "appa-renamed"); err != nil { + t.Fatalf("TriggerPostAppRenameSetup: %v", err) + } + + decoded := readVectorConfig(t) + assertComponents(t, decoded, "appa", false) + assertComponents(t, decoded, "appa-renamed", true) + + labels := lookup(t, decoded, "sources", "docker-source:appa-renamed", "include_labels") + if got := labels.([]interface{})[0]; got != "com.dokku.app-name=appa-renamed" { + t.Errorf("include_labels[0] = %v, want com.dokku.app-name=appa-renamed", got) + } +} + +// TestTriggerPostAppCloneSetupRewritesVectorConfig covers the clone case, where +// the clone inherits a sink but would otherwise have no source feeding it. +func TestTriggerPostAppCloneSetupRewritesVectorConfig(t *testing.T) { + setupScopesTest(t, []string{"appa", "appa-clone"}) + setLogsProperty(t, "appa", "vector-sink", "console://?encoding[codec]=json") + + if err := TriggerPostAppCloneSetup("appa", "appa-clone"); err != nil { + t.Fatalf("TriggerPostAppCloneSetup: %v", err) + } + + decoded := readVectorConfig(t) + assertComponents(t, decoded, "appa", true) + assertComponents(t, decoded, "appa-clone", true) +} + +// TestTriggerPostAppRenameSetupRewritesGlobalRelabel pins the generated VRL, +// which embeds app names directly as branches of the global relabel transform. +// A rename leaves a branch naming an app that no longer exists, so the renamed +// app ships under the global alias rather than its own. +func TestTriggerPostAppRenameSetupRewritesGlobalRelabel(t *testing.T) { + setupScopesTest(t, []string{"appa", "appa-renamed"}) + setLogsProperty(t, "--global", "vector-sink", "console://?encoding[codec]=json") + setLogsProperty(t, "appa", "app-label-alias", "app_name") + + source := lookup(t, readVectorConfig(t), "transforms", "docker-global-relabel", "source").(string) + if !strings.Contains(source, `app == "appa"`) { + t.Fatalf("relabel source %q missing the pre-rename branch", source) + } + + if err := TriggerPostAppRenameSetup("appa", "appa-renamed"); err != nil { + t.Fatalf("TriggerPostAppRenameSetup: %v", err) + } + + source = lookup(t, readVectorConfig(t), "transforms", "docker-global-relabel", "source").(string) + if strings.Contains(source, `app == "appa"`) { + t.Errorf("relabel source %q still names the old app", source) + } + if !strings.Contains(source, `app == "appa-renamed"`) { + t.Errorf("relabel source %q missing the renamed app", source) + } +} + func scopeByID(t *testing.T, scopes []vectorAppSinks, sourceID string) vectorAppSinks { t.Helper() diff --git a/plugins/logs/triggers.go b/plugins/logs/triggers.go index 87962efb3..10d079e55 100644 --- a/plugins/logs/triggers.go +++ b/plugins/logs/triggers.go @@ -106,14 +106,20 @@ func TriggerLogsGetProperty(appName string, key string) error { return nil } -// TriggerPostAppCloneSetup creates new logs files +// TriggerPostAppCloneSetup creates new logs files and regenerates the vector +// config so that the clone gets a source of its own for the sink it inherited func TriggerPostAppCloneSetup(oldAppName string, newAppName string) error { err := common.PropertyClone("logs", oldAppName, newAppName) if err != nil { return err } - return common.CloneAppData("logs", oldAppName, newAppName) + if err := common.CloneAppData("logs", oldAppName, newAppName); err != nil { + return err + } + + regenerateVectorConfig() + return nil } // TriggerPostAppRename removes the old app data @@ -121,7 +127,9 @@ func TriggerPostAppRename(oldAppName string, newAppName string) error { return common.MigrateAppDataDirectory("logs", oldAppName, newAppName) } -// TriggerPostAppRenameSetup renames logs files +// TriggerPostAppRenameSetup renames logs files and regenerates the vector config. +// Both app roots exist at this point, but the old app no longer has any logs +// properties, so it drops out of the generated config. func TriggerPostAppRenameSetup(oldAppName string, newAppName string) error { if err := common.PropertyClone("logs", oldAppName, newAppName); err != nil { return err @@ -131,7 +139,12 @@ func TriggerPostAppRenameSetup(oldAppName string, newAppName string) error { return err } - return common.CloneAppData("logs", oldAppName, newAppName) + if err := common.CloneAppData("logs", oldAppName, newAppName); err != nil { + return err + } + + regenerateVectorConfig() + return nil } // TriggerPostCreate ensures apps have the correct data directory structure @@ -139,11 +152,16 @@ func TriggerPostCreate(appName string) error { return common.CreateAppDataDirectory("logs", appName) } -// TriggerPostDelete destroys the logs property for a given app container +// TriggerPostDelete destroys the logs property for a given app container and +// regenerates the vector config. The regeneration runs after the properties are +// destroyed so that the app drops out of the config even though its app root is +// only removed later in the destroy flow. func TriggerPostDelete(appName string) error { dataErr := common.RemoveAppDataDirectory("logs", appName) propertyErr := common.PropertyDestroy("logs", appName) + regenerateVectorConfig() + if dataErr != nil { return dataErr } diff --git a/tests/unit/logs.bats b/tests/unit/logs-1.bats similarity index 78% rename from tests/unit/logs.bats rename to tests/unit/logs-1.bats index e3151e478..2dd39f153 100644 --- a/tests/unit/logs.bats +++ b/tests/unit/logs-1.bats @@ -692,104 +692,6 @@ teardown() { assert_success } -@test "(logs) vector validates the generated cron routing config" { - run create_app - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP vector-sink console://?encoding[codec]=json" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink console://?encoding[codec]=text" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - # unit tests cannot catch a VRL syntax error or a malformed route schema - run /bin/bash -c "docker exec vector-vector-1 vector validate --no-environment /etc/vector/vector.json" - echo "output: $output" - echo "status: $status" - assert_success - - # the relabel branches are generated VRL too, and a syntax error there would - # take the whole config down rather than just the rename - run /bin/bash -c "dokku logs:set --global vector-sink console://?encoding[codec]=json" - assert_success - - run /bin/bash -c "dokku logs:set --global app-label-alias global_alt_name" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP app-label-alias app_alt_name" - assert_success - - run /bin/bash -c "docker exec vector-vector-1 vector validate --no-environment /etc/vector/vector.json" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP app-label-alias" - assert_success - - run /bin/bash -c "dokku logs:set --global app-label-alias" - assert_success - - run /bin/bash -c "dokku logs:set --global vector-sink" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP vector-sink" - assert_success -} - -# the regression test for the alias silently disabling collection: the source -# has to keep filtering on the label dokku applies, while the event that comes -# out the other end carries the alias instead -@test "(logs) a non-default app-label-alias still ships logs" { - run create_app - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:set $TEST_APP vector-sink 'console://?encoding[codec]=json'" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:set --global app-label-alias alt_name" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run start_vector_probe VECTOR_ALIAS_OK - echo "output: $output" - echo "status: $status" - assert_success - - run wait_for_vector_alias_event VECTOR_ALIAS_OK alt_name - echo "output: $output" - echo "status: $status" - dump_vector_diagnostics "$TEST_APP" - assert_success - - run /bin/bash -c "docker container rm --force vector-alias-probe" - assert_success - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - assert_success -} - @test "(logs:report) global-vector-image and global-vector-networks raw" { run create_app assert_success @@ -899,75 +801,6 @@ teardown() { assert_output_not_exists } -@test "(logs) logs:vector-start attaches configured networks" { - docker network create test-vector-net-a >/dev/null - docker network create test-vector-net-b >/dev/null - - run /bin/bash -c "dokku logs:set --global vector-networks test-vector-net-a,test-vector-net-b 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container is running" - - run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "test-vector-net-a" - assert_output_contains "test-vector-net-b" - assert_output_contains "bridge" 0 - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container is running" - - run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "test-vector-net-a" - assert_output_contains "test-vector-net-b" - assert_output_contains "bridge" 0 - - run /bin/bash -c "dokku logs:set --global vector-networks 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "bridge" - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - echo "output: $output" - echo "status: $status" - assert_success -} - @test "(logs) logs:set app-label-alias" { run create_app echo "output: $output" @@ -1137,6 +970,151 @@ teardown() { assert_success } +@test "(logs) vector.json drops a destroyed app" { + local DESTROYED_APP="${TEST_APP}-destroyed" + + run create_app + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku apps:create $DESTROYED_APP" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku logs:set $DESTROYED_APP vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "jq -e '.sources | has(\"docker-source:$DESTROYED_APP\")' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku --force apps:destroy $DESTROYED_APP" + echo "output: $output" + echo "status: $status" + assert_success + + # an orphaned sink keeps pointing at an endpoint decommissioned with the app + run /bin/bash -c "jq -e '(.sources | has(\"docker-source:$DESTROYED_APP\")) or (.sinks | has(\"docker-sink:$DESTROYED_APP\"))' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_failure + + run /bin/bash -c "jq -e '.sources | has(\"docker-source:$TEST_APP\")' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_success +} + +@test "(logs) vector.json follows a renamed app" { + local RENAMED_APP="${TEST_APP}-renamed" + + run create_app + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku apps:rename --skip-deploy $TEST_APP $RENAMED_APP" + echo "output: $output" + echo "status: $status" + assert_success + + # the sink property follows the app, so a stale config leaves the app with a + # sink and no source feeding it + run /bin/bash -c "dokku logs:report $RENAMED_APP --logs-computed-vector-sink" + echo "output: $output" + echo "status: $status" + assert_output "console://redacted" + + run /bin/bash -c "jq -r '.sources[\"docker-source:$RENAMED_APP\"].include_labels[0]' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_output "com.dokku.app-name=$RENAMED_APP" + + run /bin/bash -c "jq -e '(.sources | has(\"docker-source:$TEST_APP\")) or (.sinks | has(\"docker-sink:$TEST_APP\"))' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_failure + + TEST_APP="$RENAMED_APP" +} + +@test "(logs) vector.json adds a source for a cloned app" { + local CLONE_APP="${TEST_APP}-clone" + + run create_app + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku apps:clone --skip-deploy $TEST_APP $CLONE_APP" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "jq -r '.sources[\"docker-source:$CLONE_APP\"].include_labels[0]' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_output "com.dokku.app-name=$CLONE_APP" + + run /bin/bash -c "jq -e '.sinks | has(\"docker-sink:$CLONE_APP\")' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "jq -e '.sources | has(\"docker-source:$TEST_APP\")' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku --force apps:destroy $CLONE_APP" + echo "output: $output" + echo "status: $status" + assert_success +} + +@test "(logs) vector.json global relabel follows a renamed app" { + local RENAMED_APP="${TEST_APP}-renamed" + + run create_app + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set --global vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP app-label-alias app_alt_name" + assert_success + + run /bin/bash -c "dokku apps:rename --skip-deploy $TEST_APP $RENAMED_APP" + echo "output: $output" + echo "status: $status" + assert_success + + # the relabel branches are generated VRL with app names baked in, so a rename + # leaves a branch naming an app that no longer exists + run /bin/bash -c "jq -r '.transforms[\"docker-global-relabel\"].source' /var/lib/dokku/data/logs/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "if app == \"$RENAMED_APP\"" + assert_output_not_contains "if app == \"$TEST_APP\"" + + TEST_APP="$RENAMED_APP" +} + @test "(logs) logs:set max-size with alternate log-driver daemon" { if [[ "$REMOTE_CONTAINERS" == "true" ]]; then skip "skipping due non-existent docker service in remote dev container" @@ -1257,76 +1235,6 @@ teardown() { assert_output "--restart=on-failure:10" } -@test "(logs) logs:vector" { - run /bin/bash -c "dokku logs:vector-logs 2>&1" - echo "output: $output" - echo "status: $status" - assert_failure - assert_output_contains "Vector container does not exist" - - run /bin/bash -c "dokku apps:create example.com" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container is running" - - run /bin/bash -c "sudo docker inspect --format='{{.HostConfig.RestartPolicy.Name}}' vector-vector-1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output "unless-stopped" - - run /bin/bash -c "dokku logs:vector-logs 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container logs" - - run /bin/bash -c "dokku --force apps:destroy example.com" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-logs --num 10 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container logs" - assert_output_contains "vector:" 10 - assert_line_count 11 - - run /bin/bash -c "dokku logs:vector-logs --num 5 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container logs" - assert_output_contains "vector:" 5 - assert_line_count 6 - - run /bin/bash -c "docker stop vector-vector-1" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku logs:vector-logs 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Vector container logs" - assert_output_contains "Vector container is not running" - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - assert_output_contains "Stopping and removing vector container" -} - @test "(logs:report) emits new stripped JSON keys alongside legacy" { run create_app assert_success @@ -1351,168 +1259,3 @@ teardown() { assert_success assert_output "true" } - -@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" - assert_success - - cron_id="$(dokku cron:list $TEST_APP --format json | jq -r '.[0].id')" - echo "cron_id: $cron_id" - - run /bin/bash -c "dokku logs:vector-start 2>&1" - echo "output: $output" - echo "status: $status" - assert_success - - # 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 'console://?encoding[codec]=json'" - echo "output: $output" - echo "status: $status" - assert_success - - # vector reloads via --watch-config, so wait for the routing to be live - run wait_for_vector_route "$TEST_APP" - echo "output: $output" - echo "status: $status" - assert_success - - run /bin/bash -c "dokku cron:run $TEST_APP $cron_id" - echo "output: $output" - echo "status: $status" - assert_success - - run wait_for_vector_cron_event VECTOR_CRON_OK "$cron_id" - echo "output: $output" - echo "status: $status" - dump_vector_diagnostics "$TEST_APP" - assert_success - - # 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" - - run /bin/bash -c "dokku logs:vector-stop 2>&1" - assert_success -} - -wait_for_vector_route() { - declare desc="waits for the vector config on disk to contain the app's cron router" - declare APP="$1" - local i - - for i in $(seq 1 30); do - if jq -e ".transforms[\"docker-router:$APP\"]" /var/lib/dokku/data/logs/vector.json >/dev/null 2>&1; then - return 0 - fi - sleep 1 - done - - echo "timed out waiting for the cron router in vector.json" - return 1 -} - -start_vector_probe() { - declare desc="runs a container carrying only the label dokku applies, emitting a marker for long enough for vector to attach" - declare MARKER="$1" - - docker container run --detach --name vector-alias-probe \ - --label "com.dokku.app-name=$TEST_APP" \ - gliderlabs/herokuish \ - bash -c "for i in \$(seq 1 30); do echo $MARKER; sleep 1; done" -} - -wait_for_vector_alias_event() { - declare desc="waits for a marker to arrive carrying the configured alias in place of the default label" - declare MARKER="$1" ALIAS="$2" - local i - - for i in $(seq 1 60); do - if docker logs vector-vector-1 2>/dev/null | grep "$MARKER" \ - | jq -e --arg alias "$ALIAS" \ - 'select(.label[$alias] != null and .label["com.dokku.app-name"] == null)' >/dev/null 2>/dev/null; then - return 0 - fi - sleep 1 - done - - echo "timed out waiting for a $MARKER event labelled $ALIAS" - return 1 -} - -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 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 a cron-routed $MARKER event with dokku_cron_id=$CRON_ID" - return 1 -} - -count_vector_plain_lines() { - declare desc="counts bare message lines, which only the text-encoded plain sink emits" - declare MARKER="$1" - - 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" - - # 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 "--- 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 -20 || true -} - -template_cron_file_marker() { - declare desc="writes an app.json with a cron task emitting a known 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": "python3 cron_task.py VECTOR_CRON_OK", - "schedule": "@daily" - } - ] -} -EOF -} diff --git a/tests/unit/logs-2.bats b/tests/unit/logs-2.bats new file mode 100644 index 000000000..d35631e80 --- /dev/null +++ b/tests/unit/logs-2.bats @@ -0,0 +1,425 @@ +#!/usr/bin/env bats + +load test_helper + +setup() { + rm "${BATS_PARENT_TMPNAME}.skip" || true + global_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 + dokku logs:set --global vector-cron-sink >/dev/null 2>/dev/null || true + docker network rm test-vector-net-a >/dev/null || true + docker network rm test-vector-net-b >/dev/null || true + global_teardown +} + +@test "(logs) vector validates the generated cron routing config" { + run create_app + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink console://?encoding[codec]=text" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + # unit tests cannot catch a VRL syntax error or a malformed route schema + run /bin/bash -c "docker exec vector-vector-1 vector validate --no-environment /etc/vector/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + + # the relabel branches are generated VRL too, and a syntax error there would + # take the whole config down rather than just the rename + run /bin/bash -c "dokku logs:set --global vector-sink console://?encoding[codec]=json" + assert_success + + run /bin/bash -c "dokku logs:set --global app-label-alias global_alt_name" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP app-label-alias app_alt_name" + assert_success + + run /bin/bash -c "docker exec vector-vector-1 vector validate --no-environment /etc/vector/vector.json" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP app-label-alias" + assert_success + + run /bin/bash -c "dokku logs:set --global app-label-alias" + assert_success + + run /bin/bash -c "dokku logs:set --global vector-sink" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-cron-sink" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink" + assert_success +} + +# the regression test for the alias silently disabling collection: the source +# has to keep filtering on the label dokku applies, while the event that comes +# out the other end carries the alias instead +@test "(logs) a non-default app-label-alias still ships logs" { + run create_app + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set $TEST_APP vector-sink 'console://?encoding[codec]=json'" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:set --global app-label-alias alt_name" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run start_vector_probe VECTOR_ALIAS_OK + echo "output: $output" + echo "status: $status" + assert_success + + run wait_for_vector_alias_event VECTOR_ALIAS_OK alt_name + echo "output: $output" + echo "status: $status" + dump_vector_diagnostics "$TEST_APP" + assert_success + + run /bin/bash -c "docker container rm --force vector-alias-probe" + assert_success + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + assert_success +} + +@test "(logs) logs:vector-start attaches configured networks" { + docker network create test-vector-net-a >/dev/null + docker network create test-vector-net-b >/dev/null + + run /bin/bash -c "dokku logs:set --global vector-networks test-vector-net-a,test-vector-net-b 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container is running" + + run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "test-vector-net-a" + assert_output_contains "test-vector-net-b" + assert_output_contains "bridge" 0 + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container is running" + + run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "test-vector-net-a" + assert_output_contains "test-vector-net-b" + assert_output_contains "bridge" 0 + + run /bin/bash -c "dokku logs:set --global vector-networks 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "sudo docker inspect --format='{{range \$k, \$v := .NetworkSettings.Networks}}{{\$k}} {{end}}' vector-vector-1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "bridge" + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + echo "output: $output" + echo "status: $status" + assert_success +} + +@test "(logs) logs:vector" { + run /bin/bash -c "dokku logs:vector-logs 2>&1" + echo "output: $output" + echo "status: $status" + assert_failure + assert_output_contains "Vector container does not exist" + + run /bin/bash -c "dokku apps:create example.com" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container is running" + + run /bin/bash -c "sudo docker inspect --format='{{.HostConfig.RestartPolicy.Name}}' vector-vector-1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output "unless-stopped" + + run /bin/bash -c "dokku logs:vector-logs 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container logs" + + run /bin/bash -c "dokku --force apps:destroy example.com" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-logs --num 10 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container logs" + assert_output_contains "vector:" 10 + assert_line_count 11 + + run /bin/bash -c "dokku logs:vector-logs --num 5 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container logs" + assert_output_contains "vector:" 5 + assert_line_count 6 + + run /bin/bash -c "docker stop vector-vector-1" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku logs:vector-logs 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Vector container logs" + assert_output_contains "Vector container is not running" + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + assert_output_contains "Stopping and removing vector container" +} + +@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" + assert_success + + cron_id="$(dokku cron:list $TEST_APP --format json | jq -r '.[0].id')" + echo "cron_id: $cron_id" + + run /bin/bash -c "dokku logs:vector-start 2>&1" + echo "output: $output" + echo "status: $status" + assert_success + + # 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 'console://?encoding[codec]=json'" + echo "output: $output" + echo "status: $status" + assert_success + + # vector reloads via --watch-config, so wait for the routing to be live + run wait_for_vector_route "$TEST_APP" + echo "output: $output" + echo "status: $status" + assert_success + + run /bin/bash -c "dokku cron:run $TEST_APP $cron_id" + echo "output: $output" + echo "status: $status" + assert_success + + run wait_for_vector_cron_event VECTOR_CRON_OK "$cron_id" + echo "output: $output" + echo "status: $status" + dump_vector_diagnostics "$TEST_APP" + assert_success + + # 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" + + run /bin/bash -c "dokku logs:vector-stop 2>&1" + assert_success +} + +wait_for_vector_route() { + declare desc="waits for the vector config on disk to contain the app's cron router" + declare APP="$1" + local i + + for i in $(seq 1 30); do + if jq -e ".transforms[\"docker-router:$APP\"]" /var/lib/dokku/data/logs/vector.json >/dev/null 2>&1; then + return 0 + fi + sleep 1 + done + + echo "timed out waiting for the cron router in vector.json" + return 1 +} + +start_vector_probe() { + declare desc="runs a container carrying only the label dokku applies, emitting a marker for long enough for vector to attach" + declare MARKER="$1" + + docker container run --detach --name vector-alias-probe \ + --label "com.dokku.app-name=$TEST_APP" \ + gliderlabs/herokuish \ + bash -c "for i in \$(seq 1 30); do echo $MARKER; sleep 1; done" +} + +wait_for_vector_alias_event() { + declare desc="waits for a marker to arrive carrying the configured alias in place of the default label" + declare MARKER="$1" ALIAS="$2" + local i + + for i in $(seq 1 60); do + if docker logs vector-vector-1 2>/dev/null | grep "$MARKER" \ + | jq -e --arg alias "$ALIAS" \ + 'select(.label[$alias] != null and .label["com.dokku.app-name"] == null)' >/dev/null 2>/dev/null; then + return 0 + fi + sleep 1 + done + + echo "timed out waiting for a $MARKER event labelled $ALIAS" + return 1 +} + +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 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 a cron-routed $MARKER event with dokku_cron_id=$CRON_ID" + return 1 +} + +count_vector_plain_lines() { + declare desc="counts bare message lines, which only the text-encoded plain sink emits" + declare MARKER="$1" + + 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" + + # 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 "--- 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 -20 || true +} + +template_cron_file_marker() { + declare desc="writes an app.json with a cron task emitting a known 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": "python3 cron_task.py VECTOR_CRON_OK", + "schedule": "@daily" + } + ] +} +EOF +}