From 1a78cdfc85945bed313f60b25407ab23a3c9bd8b Mon Sep 17 00:00:00 2001 From: Piotr Grabowski Date: Fri, 20 Dec 2024 12:03:26 +0100 Subject: [PATCH] Print container logs when integration test fails (#1127) We see (relatively rarely) integration tests being flaky. In those cases of flakiness the current logging is not sufficient to really understand the cause of the problem. This PR aims to improve logging by printing logs of all containers when a test fails. `printContainerLogs` is added to `Containers.Cleanup()` code to print the logs of containers. Additionally, the `Cleanup()` function is now **always** called, even if the containers failed to start or tests failed. To make sure it can print some logs: - the code now has less panics, which would have prevented `Cleanup()` from running - in `setupClickHouse()` and others we return the container object in case container failed to start instead of `nil` (but still with error) to be able to recover some logs - if one container fails to start, `Containers` is now returned partially filled (but still with error), so that we can print some logs instead of giving up entirely --------- Signed-off-by: Piotr Grabowski Co-authored-by: Jacek Migdal --- ci/it/integration_test.go | 2 +- ci/it/testcases/base.go | 8 +- ci/it/testcases/test_ab.go | 5 +- .../test_dual_write_and_common_table.go | 5 +- ci/it/testcases/test_ingest.go | 5 +- .../test_reading_clickhouse_tables.go | 5 +- ci/it/testcases/test_transparent_proxy.go | 5 +- ci/it/testcases/test_two_pipelines.go | 5 +- ci/it/testcases/test_wildcard_clickhouse.go | 5 +- ci/it/testcases/test_wildcard_disabled.go | 5 +- ci/it/testcases/utils.go | 171 +++++++++++++----- 11 files changed, 137 insertions(+), 84 deletions(-) diff --git a/ci/it/integration_test.go b/ci/it/integration_test.go index 65b2f8f9a..e3087bf56 100644 --- a/ci/it/integration_test.go +++ b/ci/it/integration_test.go @@ -11,13 +11,13 @@ import ( func runIntegrationTest(t *testing.T, testCase testcases.TestCase) { ctx := context.Background() + defer testCase.Cleanup(ctx, t) if err := testCase.SetupContainers(ctx); err != nil { t.Fatalf("Failed to setup containers: %s", err) } if err := testCase.RunTests(ctx, t); err != nil { t.Fatalf("Failed to run tests: %s", err) } - testCase.Cleanup(ctx) } func TestTransparentProxy(t *testing.T) { diff --git a/ci/it/testcases/base.go b/ci/it/testcases/base.go index a9c510384..801986d9a 100644 --- a/ci/it/testcases/base.go +++ b/ci/it/testcases/base.go @@ -20,7 +20,7 @@ import ( type TestCase interface { SetupContainers(ctx context.Context) error RunTests(ctx context.Context, t *testing.T) error - Cleanup(ctx context.Context) + Cleanup(ctx context.Context, t *testing.T) } type IntegrationTestcaseBase struct { @@ -36,8 +36,10 @@ func (tc *IntegrationTestcaseBase) RunTests(ctx context.Context, t *testing.T) e return nil } -func (tc *IntegrationTestcaseBase) Cleanup(ctx context.Context) { - tc.Containers.Cleanup(ctx) +func (tc *IntegrationTestcaseBase) Cleanup(ctx context.Context, t *testing.T) { + if tc.Containers != nil { + tc.Containers.Cleanup(ctx, t) + } } func (tc *IntegrationTestcaseBase) getQuesmaEndpoint() string { diff --git a/ci/it/testcases/test_ab.go b/ci/it/testcases/test_ab.go index f34b54996..ee0fe4afa 100644 --- a/ci/it/testcases/test_ab.go +++ b/ci/it/testcases/test_ab.go @@ -34,11 +34,8 @@ func NewABTestcase() *ABTestcase { func (a *ABTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *ABTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_dual_write_and_common_table.go b/ci/it/testcases/test_dual_write_and_common_table.go index 7197c3eec..d2c8715e8 100644 --- a/ci/it/testcases/test_dual_write_and_common_table.go +++ b/ci/it/testcases/test_dual_write_and_common_table.go @@ -26,11 +26,8 @@ func NewDualWriteAndCommonTableTestcase() *DualWriteAndCommonTableTestcase { func (a *DualWriteAndCommonTableTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *DualWriteAndCommonTableTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_ingest.go b/ci/it/testcases/test_ingest.go index 0178bf46e..ac1ffc4f9 100644 --- a/ci/it/testcases/test_ingest.go +++ b/ci/it/testcases/test_ingest.go @@ -28,11 +28,8 @@ func NewIngestTestcase() *IngestTestcase { func (a *IngestTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *IngestTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_reading_clickhouse_tables.go b/ci/it/testcases/test_reading_clickhouse_tables.go index b1dbc751a..074c27f94 100644 --- a/ci/it/testcases/test_reading_clickhouse_tables.go +++ b/ci/it/testcases/test_reading_clickhouse_tables.go @@ -26,11 +26,8 @@ func NewReadingClickHouseTablesIntegrationTestcase() *ReadingClickHouseTablesInt func (a *ReadingClickHouseTablesIntegrationTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *ReadingClickHouseTablesIntegrationTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_transparent_proxy.go b/ci/it/testcases/test_transparent_proxy.go index 822c9a257..9b73aa6f4 100644 --- a/ci/it/testcases/test_transparent_proxy.go +++ b/ci/it/testcases/test_transparent_proxy.go @@ -25,11 +25,8 @@ func NewTransparentProxyIntegrationTestcase() *TransparentProxyIntegrationTestca func (a *TransparentProxyIntegrationTestcase) SetupContainers(ctx context.Context) error { containers, err := setupContainersForTransparentProxy(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *TransparentProxyIntegrationTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_two_pipelines.go b/ci/it/testcases/test_two_pipelines.go index 66a8850ff..2d637fecc 100644 --- a/ci/it/testcases/test_two_pipelines.go +++ b/ci/it/testcases/test_two_pipelines.go @@ -25,11 +25,8 @@ func NewQueryAndIngestPipelineTestcase() *QueryAndIngestPipelineTestcase { func (a *QueryAndIngestPipelineTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *QueryAndIngestPipelineTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_wildcard_clickhouse.go b/ci/it/testcases/test_wildcard_clickhouse.go index 8aa914183..7970bd16c 100644 --- a/ci/it/testcases/test_wildcard_clickhouse.go +++ b/ci/it/testcases/test_wildcard_clickhouse.go @@ -25,11 +25,8 @@ func NewWildcardClickhouseTestcase() *WildcardClickhouseTestcase { func (a *WildcardClickhouseTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *WildcardClickhouseTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/test_wildcard_disabled.go b/ci/it/testcases/test_wildcard_disabled.go index bc186ea19..5509ca6a5 100644 --- a/ci/it/testcases/test_wildcard_disabled.go +++ b/ci/it/testcases/test_wildcard_disabled.go @@ -25,11 +25,8 @@ func NewWildcardDisabledTestcase() *WildcardDisabledTestcase { func (a *WildcardDisabledTestcase) SetupContainers(ctx context.Context) error { containers, err := setupAllContainersWithCh(ctx, a.ConfigTemplate) - if err != nil { - return err - } a.Containers = containers - return nil + return err } func (a *WildcardDisabledTestcase) RunTests(ctx context.Context, t *testing.T) error { diff --git a/ci/it/testcases/utils.go b/ci/it/testcases/utils.go index 89b6143bd..1d6772b91 100644 --- a/ci/it/testcases/utils.go +++ b/ci/it/testcases/utils.go @@ -10,10 +10,12 @@ import ( "github.com/docker/docker/api/types/container" "github.com/testcontainers/testcontainers-go" "github.com/testcontainers/testcontainers-go/wait" + "io" "log" "os" "path/filepath" "strings" + "testing" "text/template" "time" ) @@ -34,21 +36,103 @@ type Containers struct { ClickHouse *testcontainers.Container } -func (c *Containers) Cleanup(ctx context.Context) { - if c.Elasticsearch != nil { - (*c.Elasticsearch).Terminate(ctx) +// Read the last X bytes from the reader and return the last N lines from that +// Requires two readers because io.Reader doesn't support seeking +func tail(reader io.Reader, readerCopy io.Reader) ([]string, error) { + // Size of chunk to read from the end (1MB) + const chunkSize = 1024 * 1024 + // Maximum number of lines to return + const maxLines = 1000 + + totalSize, err := io.Copy(io.Discard, reader) + if err != nil { + return nil, err + } + + skip := totalSize - chunkSize + if skip > 0 { + _, err = io.CopyN(io.Discard, readerCopy, skip) + if err != nil && err != io.EOF { + return nil, err + } + } + + output, err := io.ReadAll(readerCopy) + if err != nil { + return nil, err + } + + lines := strings.Split(string(output), "\n") + + if len(lines) > maxLines { + lines = lines[len(lines)-maxLines:] + } + + // The chunk could have started in the middle of a line, so we skip the first line + if len(lines) > 0 { + lines = lines[1:] + } + + return lines, nil +} + +func printContainerLogs(ctx context.Context, container *testcontainers.Container, name string) { + if container == nil { + return + } + + reader, err := (*container).Logs(ctx) + if err != nil { + log.Printf("Failed to get logs for container '%s': %v", name, err) + return + } + defer reader.Close() + + readerCopy, err := (*container).Logs(ctx) + if err != nil { + log.Printf("Failed to get logs for container '%s': %v", name, err) + return + } + defer readerCopy.Close() + + lines, err := tail(reader, readerCopy) + if err != nil { + log.Printf("Failed to read logs for container '%s': %v", name, err) + return } - if c.Quesma != nil { - (*c.Quesma).Terminate(ctx) + + log.Printf("Logs for container '%s':", name) + for _, line := range lines { + log.Printf("[%s]: %s", name, line) } - if c.Kibana != nil { - (*c.Kibana).Terminate(ctx) +} + +func terminateContainer(ctx context.Context, container *testcontainers.Container, name string) { + if container == nil { + log.Printf("Container '%s' is nil", name) + return } - if c.ClickHouse != nil { - (*c.ClickHouse).Terminate(ctx) + + err := (*container).Terminate(ctx) + if err != nil { + log.Printf("Failed to terminate container '%s': %v", name, err) } } +func (c *Containers) Cleanup(ctx context.Context, t *testing.T) { + if t.Failed() { + printContainerLogs(ctx, c.Elasticsearch, "Elasticsearch") + printContainerLogs(ctx, c.Quesma, "Quesma") + printContainerLogs(ctx, c.Kibana, "Kibana") + printContainerLogs(ctx, c.ClickHouse, "ClickHouse") + } + + terminateContainer(ctx, c.Elasticsearch, "Elasticsearch") + terminateContainer(ctx, c.Quesma, "Quesma") + terminateContainer(ctx, c.Kibana, "Kibana") + terminateContainer(ctx, c.ClickHouse, "ClickHouse") +} + func setupElasticsearch(ctx context.Context) (testcontainers.Container, error) { req := testcontainers.ContainerRequest{ Image: "docker.elastic.co/elasticsearch/elasticsearch:8.11.1", @@ -74,7 +158,7 @@ func setupElasticsearch(ctx context.Context) (testcontainers.Container, error) { Started: true, }) if err != nil { - return nil, err + return elasticsearch, err } // Set password to Kibana system user @@ -82,7 +166,7 @@ func setupElasticsearch(ctx context.Context) (testcontainers.Container, error) { output := new(bytes.Buffer) output.ReadFrom(reader) log.Printf("Command output: %s", output.String()) - panic(fmt.Sprintf("Failed to set password for kibana_system: returned=[%d] err=[%v]", retCode, errCmd)) + return elasticsearch, fmt.Errorf("Failed to set password for kibana_system: returned=[%d] err=[%v]", retCode, errCmd) } return elasticsearch, nil @@ -119,14 +203,10 @@ func setupQuesma(ctx context.Context, quesmaConfig string) (testcontainers.Conta }, } - quesma, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ + return testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: quesmaReq, Started: true, }) - if err != nil { - return nil, err - } - return quesma, nil } func setupKibana(ctx context.Context, quesmaContainer testcontainers.Container) (testcontainers.Container, error) { @@ -152,14 +232,10 @@ func setupKibana(ctx context.Context, quesmaContainer testcontainers.Container) }, WaitingFor: wait.ForLog("http server running at").WithStartupTimeout(4 * time.Minute), } - kibana, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ + return testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: req, Started: true, }) - if err != nil { - return nil, err - } - return kibana, nil } func setupClickHouse(ctx context.Context) (testcontainers.Container, error) { @@ -171,14 +247,10 @@ func setupClickHouse(ctx context.Context) (testcontainers.Container, error) { }, WaitingFor: wait.ForExposedPort().WithStartupTimeout(2 * time.Minute), } - clickhouse, err := testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ + return testcontainers.GenericContainer(ctx, testcontainers.GenericContainerRequest{ ContainerRequest: req, Started: true, }) - if err != nil { - return nil, err - } - return clickhouse, nil } func RenderQuesmaConfig(configTemplate string, data map[string]string) error { @@ -204,49 +276,55 @@ func RenderQuesmaConfig(configTemplate string, data map[string]string) error { } func setupContainersForTransparentProxy(ctx context.Context, quesmaConfigTemplate string) (*Containers, error) { + containers := Containers{} + elasticsearch, err := setupElasticsearch(ctx) + containers.Elasticsearch = &elasticsearch if err != nil { - log.Fatalf("Failed to start Elasticsearch container: %s", err) + return &containers, fmt.Errorf("failed to start Elasticsearch container: %s", err) } - esPort, _ := elasticsearch.MappedPort(ctx, "9200/tcp") + data := map[string]string{ "elasticsearch_host": GetInternalDockerHost(), "elasticsearch_port": esPort.Port(), } if err := RenderQuesmaConfig(quesmaConfigTemplate, data); err != nil { - log.Fatalf("Failed to render Quesma config: %s", err) + return &containers, fmt.Errorf("failed to render Quesma config: %v", err) } quesma, err := setupQuesma(ctx, quesmaConfigTemplate) + containers.Quesma = &quesma if err != nil { - println(err) + return &containers, fmt.Errorf("failed to start Quesma, %v", err) } kibana, err := setupKibana(ctx, quesma) + containers.Kibana = &kibana if err != nil { - log.Fatalf("Failed to start Kibana container: %s", err) + return &containers, fmt.Errorf("failed to start Kibana container: %v", err) } - return &Containers{ - Elasticsearch: &elasticsearch, - Quesma: &quesma, - Kibana: &kibana, - ClickHouse: nil, - }, nil + return &containers, nil } func setupAllContainersWithCh(ctx context.Context, quesmaConfigTemplate string) (*Containers, error) { + containers := Containers{} + elasticsearch, err := setupElasticsearch(ctx) + containers.Elasticsearch = &elasticsearch if err != nil { - log.Fatalf("Failed to start Elasticsearch container: %s", err) + return &containers, fmt.Errorf("failed to start Elasticsearch container: %s", err) } + esPort, _ := elasticsearch.MappedPort(ctx, "9200/tcp") clickhouse, err := setupClickHouse(ctx) + containers.ClickHouse = &clickhouse if err != nil { - log.Fatalf("Failed to start ClickHouse container: %s", err) + return &containers, fmt.Errorf("failed to start ClickHouse container: %s", err) } + chPort, _ := clickhouse.MappedPort(ctx, "9000/tcp") data := map[string]string{ @@ -256,23 +334,20 @@ func setupAllContainersWithCh(ctx context.Context, quesmaConfigTemplate string) "clickhouse_port": chPort.Port(), } if err := RenderQuesmaConfig(quesmaConfigTemplate, data); err != nil { - log.Fatalf("Failed to render Quesma config: %v", err) + return &containers, fmt.Errorf("failed to render Quesma config: %v", err) } quesma, err := setupQuesma(ctx, quesmaConfigTemplate) + containers.Quesma = &quesma if err != nil { - log.Fatalf("Failed to start Quesma, %v", err) + return &containers, fmt.Errorf("failed to start Quesma, %v", err) } kibana, err := setupKibana(ctx, quesma) + containers.Kibana = &kibana if err != nil { - log.Fatalf("Failed to start Kibana container: %v", err) + return &containers, fmt.Errorf("failed to start Kibana container: %v", err) } - return &Containers{ - Elasticsearch: &elasticsearch, - Quesma: &quesma, - Kibana: &kibana, - ClickHouse: &clickhouse, - }, nil + return &containers, nil }