Better debug logs on failed tests

Print the database logs when an e2e test fails.
timescale · Apr 6, 2022 · ac605ef · ac605ef
1 parent 9e7afaf
commit ac605ef
Show file tree

Hide file tree

Showing 5 changed files with 85 additions and 18 deletions.
diff --git a/pkg/internal/testhelpers/containers.go b/pkg/internal/testhelpers/containers.go
@@ -6,7 +6,9 @@ package testhelpers
 
 import (
 	"context"
+	"encoding/binary"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"os"
 	"runtime"
@@ -37,7 +39,54 @@ func (s stdoutLogConsumer) Accept(l testcontainers.Log) {
 	}
 }
 
-func StopContainer(ctx context.Context, container testcontainers.Container, printLogs bool) {
+func PrintContainerLogs(container testcontainers.Container) {
+	logs, err := container.Logs(context.TODO())
+	if err != nil {
+		fmt.Println("Error fetching logs: ", err)
+		return
+	}
+	defer logs.Close()
+
+	logSlice := make([]string, 0)
+	h := make([]byte, 8)
+	for {
+		_, err := logs.Read(h)
+		if err != nil {
+			if err == io.EOF {
+				break
+			}
+			fmt.Println("Error reading from logs: ", err)
+			return
+		}
+
+		count := binary.BigEndian.Uint32(h[4:])
+		if count == 0 {
+			continue
+		}
+		b := make([]byte, count)
+		_, err = logs.Read(b)
+		if err != nil {
+			if err == io.EOF {
+				break
+			}
+			fmt.Println("Error reading from logs: ", err)
+			return
+		}
+		logSlice = append(logSlice, string(b))
+	}
+
+	fmt.Printf("DB container logs (last 100 lines): \n")
+	n := len(logSlice) - 100 /* get last 100 lines */
+	if n < 0 {
+		n = 0
+	}
+	fmt.Println(logSlice[n:])
+}
+
+func StopContainer(ctx context.Context, container testcontainers.Container, printLogs bool, t Result) {
+	if !printLogs && t != nil && t.Failed() {
+		PrintContainerLogs(container)
+	}
 	if printLogs {
 		err := container.StopLogProducer()
 		if err != nil {

diff --git a/pkg/internal/testhelpers/containers_test.go b/pkg/internal/testhelpers/containers_test.go
@@ -66,7 +66,7 @@ func runMain(m *testing.M) int {
 	// TODO (james): Replace hardcoded value
 	extensionState := NewTestOptions(timescaleBit, "ghcr.io/timescale/dev_promscale_extension:develop-ts2-pg14")
 	if !testing.Short() && *useDocker {
-		_, closer, err := StartPGContainer(ctx, extensionState, "", false)
+		_, closer, err := StartPGContainer(ctx, nil, extensionState, "", false)
 		if err != nil {
 			fmt.Println("Error setting up container", err)
 			os.Exit(1)

diff --git a/pkg/internal/testhelpers/postgres_container.go b/pkg/internal/testhelpers/postgres_container.go
@@ -36,6 +36,10 @@ const (
 	NoSuperuser = false
 )
 
+type Result interface {
+	Failed() bool
+}
+
 var (
 	users = []string{
 		promUser,
@@ -286,16 +290,18 @@ func DbSetup(DBName string, superuser SuperuserStatus, deferNode2Setup bool, ext
 // StartPGContainer starts a postgreSQL container for use in testing
 func StartPGContainer(
 	ctx context.Context,
+	t Result,
 	extensionState TestOptions,
 	testDataDir string,
 	printLogs bool,
 ) (testcontainers.Container, io.Closer, error) {
 	image := extensionState.GetDockerImageName()
 
-	return StartDatabaseImage(ctx, image, testDataDir, "", printLogs, extensionState)
+	return StartDatabaseImage(ctx, t, image, testDataDir, "", printLogs, extensionState)
 }
 
 func StartDatabaseImage(ctx context.Context,
+	t Result,
 	image string,
 	testDataDir string,
 	dataDir string,
@@ -316,6 +322,7 @@ func StartDatabaseImage(ctx context.Context,
 	startContainer := func(containerPort nat.Port) (testcontainers.Container, error) {
 		container, closer, err := startPGInstance(
 			ctx,
+			t,
 			image,
 			testDataDir,
 			dataDir,
@@ -442,6 +449,7 @@ func removeTimescaleExtension(container testcontainers.Container) error {
 
 func startPGInstance(
 	ctx context.Context,
+	t Result,
 	image string,
 	testDataDir string,
 	dataDir string,
@@ -462,7 +470,7 @@ func startPGInstance(
 		ExposedPorts: []string{string(containerPort)},
 		WaitingFor: wait.ForSQL(containerPort, "pgx", func(port nat.Port) string {
 			return "dbname=postgres password=password user=postgres host=127.0.0.1 port=" + port.Port()
-		}).Timeout(120 * time.Second),
+		}).Timeout(60 * time.Second),
 		Env: map[string]string{
 			"POSTGRES_PASSWORD": "password",
 			"PGDATA":            "/var/lib/postgresql/data",
@@ -531,6 +539,7 @@ func startPGInstance(
 
 	err = container.Start(context.Background())
 	if err != nil {
+		PrintContainerLogs(container)
 		return nil, nil, err
 	}
 
@@ -543,7 +552,7 @@ func startPGInstance(
 	}
 
 	closer := func() {
-		StopContainer(ctx, container, printLogs)
+		StopContainer(ctx, container, printLogs, t)
 	}
 
 	if isDataNode {

diff --git a/pkg/tests/end_to_end_tests/main_test.go b/pkg/tests/end_to_end_tests/main_test.go
@@ -90,8 +90,16 @@ func setExtensionState() {
 	testOptions.SetTimescaleDockerImage(*timescaleDockerImage)
 }
 
+type testResult struct {
+	code int
+}
+
+func (t *testResult) Failed() bool {
+	return t.code != 0
+}
+
 func TestMain(m *testing.M) {
-	var code int
+	res := &testResult{1}
 	func() {
 		flag.Parse()
 		ctx := context.Background()
@@ -111,6 +119,7 @@ func TestMain(m *testing.M) {
 
 			pgContainer, closer, err = testhelpers.StartPGContainer(
 				ctx,
+				res,
 				testOptions,
 				pgContainerTestDataDir,
 				*printLogs,
@@ -154,9 +163,9 @@ func TestMain(m *testing.M) {
 				}
 			}()
 		}
-		code = m.Run()
+		res.code = m.Run()
 	}()
-	os.Exit(code)
+	os.Exit(res.code)
 }
 
 func attachDataNode2(t testing.TB, DBName string, connectURL string) {

diff --git a/pkg/tests/upgrade_tests/upgrade_test.go b/pkg/tests/upgrade_tests/upgrade_test.go
@@ -381,7 +381,7 @@ func withDBStartingAtOldVersionAndUpgrading(
 	// Start a db with the prev extension and a prev connector as well
 	// Then run preUpgrade and shut everything down.
 	func() {
-		dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, prevDBImage, tmpDir, dataDir, *printLogs, extensionState)
+		dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, t, prevDBImage, tmpDir, dataDir, *printLogs, extensionState)
 		if err != nil {
 			t.Fatal("Error setting up container", err)
 		}
@@ -400,7 +400,7 @@ func withDBStartingAtOldVersionAndUpgrading(
 		if err != nil {
 			log.Fatal(err.Error())
 		}
-		defer testhelpers.StopContainer(ctx, connector, *printLogs)
+		defer testhelpers.StopContainer(ctx, connector, *printLogs, t)
 
 		connectorHost, err := connector.Host(ctx)
 		if err != nil {
@@ -419,7 +419,7 @@ func withDBStartingAtOldVersionAndUpgrading(
 
 	//Start a new connector and migrate.
 	//Then run postUpgrade
-	dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
+	dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, t, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
 	if err != nil {
 		t.Fatal("Error setting up container", err)
 	}
@@ -466,7 +466,7 @@ func withNewDBAtCurrentVersion(t testing.TB, DBName string, extensionState testh
 	}
 
 	func() {
-		container, closer, err := testhelpers.StartDatabaseImage(ctx, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
+		container, closer, err := testhelpers.StartDatabaseImage(ctx, t, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
 		if err != nil {
 			fmt.Println("Error setting up container", err)
 			os.Exit(1)
@@ -487,7 +487,7 @@ func withNewDBAtCurrentVersion(t testing.TB, DBName string, extensionState testh
 			preRestart(container, connectURL, db, tmpDir)
 		})
 	}()
-	container, closer, err := testhelpers.StartDatabaseImage(ctx, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
+	container, closer, err := testhelpers.StartDatabaseImage(ctx, t, cleanImage, tmpDir, dataDir, *printLogs, extensionState)
 	if err != nil {
 		fmt.Println("Error setting up container", err)
 		os.Exit(1)
@@ -625,7 +625,7 @@ func TestExtensionUpgrade(t *testing.T) {
 		if err != nil {
 			t.Fatal(err)
 		}
-		defer testhelpers.StopContainer(ctx, connector, *printLogs)
+		defer testhelpers.StopContainer(ctx, connector, *printLogs, t)
 		err = db.QueryRow(ctx, `SELECT extversion FROM pg_extension where extname='timescaledb'`).Scan(&version)
 		if err != nil {
 			t.Fatal(err)
@@ -649,7 +649,7 @@ func TestExtensionUpgrade(t *testing.T) {
 		if err != nil {
 			t.Fatal(err)
 		}
-		defer testhelpers.StopContainer(ctx, connector, *printLogs)
+		defer testhelpers.StopContainer(ctx, connector, *printLogs, t)
 
 		var versionStr string
 		db, err = pgx.Connect(ctx, testhelpers.PgConnectURL("postgres", testhelpers.Superuser))
@@ -711,7 +711,7 @@ func TestMigrationFailure(t *testing.T) {
 		if err != nil {
 			t.Fatal(err)
 		}
-		defer testhelpers.StopContainer(ctx, connector, *printLogs)
+		defer testhelpers.StopContainer(ctx, connector, *printLogs, t)
 
 		db, err = pgx.Connect(ctx, testhelpers.PgConnectURL("postgres", testhelpers.Superuser))
 		if err != nil {
@@ -739,7 +739,7 @@ func TestMigrationFailure(t *testing.T) {
 		if err != nil {
 			t.Fatal(err)
 		}
-		defer testhelpers.StopContainer(ctx, connector, *printLogs)
+		defer testhelpers.StopContainer(ctx, connector, *printLogs, t)
 
 		var version string
 		db, err = pgx.Connect(ctx, testhelpers.PgConnectURL("postgres", testhelpers.Superuser))
@@ -791,7 +791,7 @@ func startDB(t *testing.T, ctx context.Context) (*pgx.Conn, testcontainers.Conta
 	// TODO (james): Replace hardcoded value
 	extensionState := testhelpers.NewTestOptions(testhelpers.Timescale, "ghcr.io/timescale/dev_promscale_extension:develop-ts2-pg14")
 
-	dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, "timescaledev/promscale-extension:testing-extension-upgrade", tmpDir, dataDir, *printLogs, extensionState)
+	dbContainer, closer, err := testhelpers.StartDatabaseImage(ctx, t, "timescaledev/promscale-extension:testing-extension-upgrade", tmpDir, dataDir, *printLogs, extensionState)
 	if err != nil {
 		t.Fatal("Error setting up container", err)
 	}