Include the contents of logs when postgres fails to start or initdb fails (fergusstrange#84)

* fix: print log contents when postgres fails to start

* fix: flush the logger before attempting to read

* test: failure is included in error when postgres fails to start

* fix: include log contents with initialization errors

* fix: flush the logger before reading

* refactor: read by file name

* test: logs are output on initialization failure

* fix: os -> ioutil for older versions of Go

* fix: os -> ioutil for older versions of Go

* lint: stop cuddling 😆

* fix: bail if we can't read the logs after 10s

* refactor: move log reading into function

* refactor: use timeout version for startPostgres too

* test: logging method

* test: error case

* test: logging method content

* fix: imports

* feat: include log reading error in log output

Author: mackinleysmith

embedded_postgres.go

@@ -219,7 +219,10 @@ func startPostgres(ep *EmbeddedPostgres) error {
 	}
 
 	if err := postgresProcess.Start(); err != nil {
-		return fmt.Errorf("could not start postgres using %s: %w", postgresProcess.String(), err)
+		_ = ep.syncedLogger.flush()
+		logContent, _ := readLogsOrTimeout(ep.syncedLogger.file)
+
+		return fmt.Errorf("could not start postgres using %s:\n%s", postgresProcess.String(), string(logContent))
 	}
 
 	waitErrC := make(chan error, 1)

embedded_postgres_test.go

@@ -226,12 +226,13 @@ func Test_ErrorWhenCannotStartPostgresProcess(t *testing.T) {
 	}
 
 	database.initDatabase = func(binaryExtractLocation, runtimePath, dataLocation, username, password, locale string, useUnixSocket string, logger *os.File) error {
+		_, _ = logger.Write([]byte("ah it did not work"))
 		return nil
 	}
 
 	err = database.Start()
 
-	assert.Contains(t, err.Error(), fmt.Sprintf(`could not start postgres using %s/bin/postgres -D %s/data -p 5432`, extractPath, extractPath))
+	assert.EqualError(t, err.Error(), fmt.Sprintf("could not start postgres using %s/bin/pg_ctl start -w -D %s/data -o \"-p 5432\":\nah it did not work", extractPath, extractPath))
 }
 
 func Test_CustomConfig(t *testing.T) {

logging.go

@@ -3,7 +3,9 @@ package embeddedpostgres
 import (
 	"fmt"
 	"io"
+	"io/ioutil"
 	"os"
+	"time"
 )
 
 type syncedLogger struct {
@@ -53,3 +55,27 @@ func (s *syncedLogger) flush() error {
 
 	return nil
 }
+
+func readLogsOrTimeout(logger *os.File) (logContent []byte, err error) {
+	logContent = []byte("logs could not be read")
+
+	logContentChan := make(chan []byte, 1)
+	errChan := make(chan error, 1)
+
+	go func() {
+		if actualLogContent, err := ioutil.ReadFile(logger.Name()); err == nil {
+			logContentChan <- actualLogContent
+		} else {
+			errChan <- err
+		}
+	}()
+
+	select {
+	case logContent = <-logContentChan:
+	case err = <-errChan:
+	case <-time.After(10 * time.Second):
+		err = fmt.Errorf("timed out waiting for logs")
+	}
+
+	return logContent, err
+}

logging_test.go

@@ -1,10 +1,13 @@
 package embeddedpostgres
 
 import (
+	"fmt"
+	"io/ioutil"
 	"os"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 type customLogger struct {
@@ -56,3 +59,25 @@ func Test_SyncedLogger_NoErrorDuringFlush(t *testing.T) {
 
 	assert.Equal(t, "some logs\non a new line", string(logger.logLines))
 }
+
+func Test_readLogsOrTimeout(t *testing.T) {
+	logFile, err := ioutil.TempFile("", "prepare_database_test_log")
+	if err != nil {
+		panic(err)
+	}
+
+	logContent, err := readLogsOrTimeout(logFile)
+	assert.NoError(t, err)
+	assert.Equal(t, []byte(""), logContent)
+
+	_, _ = logFile.Write([]byte("and here are the logs!"))
+
+	logContent, err = readLogsOrTimeout(logFile)
+	assert.NoError(t, err)
+	assert.Equal(t, []byte("and here are the logs!"), logContent)
+
+	require.NoError(t, os.Remove(logFile.Name()))
+	logContent, err = readLogsOrTimeout(logFile)
+	assert.Equal(t, []byte("logs could not be read"), logContent)
+	assert.EqualError(t, err, fmt.Sprintf("open %s: no such file or directory", logFile.Name()))
+}

prepare_database.go

@@ -46,7 +46,11 @@ func defaultInitDatabase(binaryExtractLocation, runtimePath, pgDataDir, username
 	postgresInitDBProcess.Stdout = logger
 
 	if err = postgresInitDBProcess.Run(); err != nil {
-		return fmt.Errorf("unable to init database using '%s': %w", postgresInitDBProcess.String(), err)
+		logContent, readLogsErr := readLogsOrTimeout(logger) // we want to preserve the original error
+		if readLogsErr != nil {
+			logContent = []byte(string(logContent) + " - " + readLogsErr.Error())
+		}
+		return fmt.Errorf("unable to init database using '%s': %w\n%s", postgresInitDBProcess.String(), err, string(logContent))
 	}
 
 	if err = os.Remove(passwordFile); err != nil {

prepare_database_test.go

@@ -3,6 +3,7 @@ package embeddedpostgres
 import (
 	"errors"
 	"fmt"
+	"io/ioutil"
 	"os"
 	"path/filepath"
 	"testing"
@@ -27,6 +28,11 @@ func Test_defaultInitDatabase_ErrorWhenCannotStartInitDBProcess(t *testing.T) {
 		panic(err)
 	}
 
+	logFile, err := ioutil.TempFile("", "prepare_database_test_log")
+	if err != nil {
+		panic(err)
+	}
+
 	defer func() {
 		if err := os.RemoveAll(binTempDir); err != nil {
 			panic(err)
@@ -35,15 +41,22 @@ func Test_defaultInitDatabase_ErrorWhenCannotStartInitDBProcess(t *testing.T) {
 		if err := os.RemoveAll(runtimeTempDir); err != nil {
 			panic(err)
 		}
+
+		if err := os.Remove(logFile.Name()); err != nil {
+			panic(err)
+		}
 	}()
 
-	err = defaultInitDatabase(binTempDir, runtimeTempDir, filepath.Join(runtimeTempDir, "data"), "Tom", "Beer", "", "", os.Stderr)
+	_, _ = logFile.Write([]byte("and here are the logs!"))
+
+	err = defaultInitDatabase(binTempDir, runtimeTempDir, filepath.Join(runtimeTempDir, "data"), "Tom", "Beer", "", "", logFile)
 
 	assert.NotNil(t, err)
 	assert.Contains(t, err.Error(), fmt.Sprintf("unable to init database using '%s/bin/initdb -A password --pwfile=%s/pwfile -U Tom -D %s/data'",
 		binTempDir,
 		runtimeTempDir,
 		runtimeTempDir))
+	assert.Contains(t, err.Error(), "and here are the logs!")
 	assert.FileExists(t, filepath.Join(runtimeTempDir, "pwfile"))
 }