fix: error messages got lost because in some cases

When running baur in a CI job, error messages sometimes got lost.
It was probably because stderr was not flushed in time when baur existed
in the CI environment.

The previous log implementation was not appending a newline to each
message to ensure it's flushed.
This commit switches the log package to be based on the Golang log which
takes care about it.
The S3, upload and exec package do not import the log package anymore
and offer functions to set a logger instead.

Non-error and debug messages are written to STDOUT via the fmt package.

Makefile

@@ -49,7 +49,6 @@ release: clean dirty_worktree_check dist/linux_amd64/baur dist/darwin_amd64/baur
 	@echo - git push --tags
 	@echo - upload $(ls dist/*/*.tar.xz) files
 
-
 .PHONY: check
 check:
 	$(info * running static code checks)

command/apps_builds.go

@@ -120,7 +120,7 @@ func resultAddUploadResult(appName string, ar baur.BuildOutput, r *upload.Result
 
 	b, exist := result[appName]
 	if !exist {
-		log.Fatalf("resultAddUploadResult: %q does not exist in build result map\n", appName)
+		log.Fatalf("resultAddUploadResult: %q does not exist in build result map", appName)
 	}
 
 	if r.Job.Type() == upload.JobDocker {
@@ -131,12 +131,12 @@ func resultAddUploadResult(appName string, ar baur.BuildOutput, r *upload.Result
 
 	artDigest, err := ar.Digest()
 	if err != nil {
-		log.Fatalf("getting digest for output %q failed: %s\n", ar, err)
+		log.Fatalf("getting digest for output %q failed: %s", ar, err)
 	}
 
 	arSize, err := ar.Size(&outputBackends)
 	if err != nil {
-		log.Fatalf("getting size of output %q failed: %s\n", ar, err)
+		log.Fatalf("getting size of output %q failed: %s", ar, err)
 	}
 
 	b.Outputs = append(b.Outputs, &storage.Output{
@@ -157,7 +157,7 @@ func recordResultIsComplete(app *baur.App) (bool, *storage.Build) {
 
 	b, exist := result[app.Name]
 	if !exist {
-		log.Fatalf("recordResultIfComplete: %q does not exist in build result map\n", app.Name)
+		log.Fatalf("recordResultIfComplete: %q does not exist in build result map", app.Name)
 	}
 
 	if len(app.Outputs) == len(b.Outputs) {
@@ -192,7 +192,7 @@ func calcDigests(app *baur.App) ([]*storage.Input, string) {
 	// The storageInputs can be removed, apps.BuildInputs() can be used
 	// instead to later fill the struct for the db
 
-	log.Debugf("%s: resolving build inputs and calculating digests...\n", app)
+	log.Debugf("%s: resolving build inputs and calculating digests...", app)
 	buildInputs, err := app.BuildInputs()
 	if err != nil {
 		log.Fatalf("%s: resolving build input paths failed: %s\n", app, err)
@@ -201,7 +201,7 @@ func calcDigests(app *baur.App) ([]*storage.Input, string) {
 	for _, s := range buildInputs {
 		d, err := s.Digest()
 		if err != nil {
-			log.Fatalf("%s: calculating build input digest failed: %s\n", app, err)
+			log.Fatalf("%s: calculating build input digest failed: %s", app, err)
 		}
 
 		storageInputs = append(storageInputs, &storage.Input{
@@ -215,7 +215,7 @@ func calcDigests(app *baur.App) ([]*storage.Input, string) {
 	if len(inputDigests) > 0 {
 		td, err := sha384.Sum(inputDigests)
 		if err != nil {
-			log.Fatalln("calculating total input digest failed:", err)
+			log.Fatalf("%s: calculating total input digest failed: %s", app, err)
 		}
 
 		totalDigest = td.String()
@@ -247,14 +247,14 @@ func createBuildJobs(apps []*baur.App) []*build.Job {
 
 func startBGUploader(outputCnt int, uploadChan chan *upload.Result) upload.Manager {
 	var dockerUploader *docker.Client
-	s3Uploader, err := s3.NewClient()
+	s3Uploader, err := s3.NewClient(log.StdLogger)
 	if err != nil {
 		log.Fatalln(err.Error())
 	}
 
 	dockerUser, dockerPass := dockerAuthFromEnv()
 	if len(dockerUser) != 0 {
-		log.Debugf("read docker registry auth data from %q, %q Env variables, authenticating as %q \n",
+		log.Debugf("read docker registry auth data from %q, %q Env variables, authenticating as %q",
 			dockerEnvUsernameVar, dockerEnvPasswordVar, dockerUser)
 		dockerUploader, err = docker.NewClientwAuth(dockerUser, dockerPass)
 	} else {
@@ -264,7 +264,7 @@ func startBGUploader(outputCnt int, uploadChan chan *upload.Result) upload.Manag
 		log.Fatalln(err)
 	}
 
-	uploader := sequploader.New(s3Uploader, dockerUploader, uploadChan)
+	uploader := sequploader.New(log.StdLogger, s3Uploader, dockerUploader, uploadChan)
 
 	outputBackends.DockerClt = dockerUploader
 
@@ -304,7 +304,7 @@ func waitPrintUploadStatus(uploader upload.Manager, uploadChan chan *upload.Resu
 			log.Fatalf("upload of %q failed: %s\n", ud.Output, res.Err)
 		}
 
-		log.Actionf("%s: %s uploaded to %s (%.3fs)\n",
+		fmt.Printf("%s: %s uploaded to %s (%.3fs)\n",
 			ud.App.Name, ud.Output.LocalPath(), res.URL, res.Duration.Seconds())
 
 		resultAddUploadResult(ud.App.Name, ud.Output, res)
@@ -315,7 +315,7 @@ func waitPrintUploadStatus(uploader upload.Manager, uploadChan chan *upload.Resu
 			if err := store.Save(build); err != nil {
 				log.Fatalf("storing build information about %q failed: %s", ud.App.Name, err)
 			}
-			log.Infof("%s: build %d stored in database\n", ud.App.Name, build.ID)
+			fmt.Printf("%s: build %d stored in database\n", ud.App.Name, build.ID)
 
 			log.Debugf("stored the following build information: %s\n", prettyprint.AsString(build))
 		}
@@ -341,14 +341,14 @@ func outstandingBuilds(storage storage.Storer, apps []*baur.App) []*baur.App {
 			res = append(res, app)
 		}
 
-		if !log.DebugEnabled {
+		if !verboseFlag {
 			fmt.Printf(".")
 		}
 
 		log.Debugf("\n%s: build status. %q\n", app, buildStatus)
 	}
 
-	if !log.DebugEnabled {
+	if !log.DebugEnabled() {
 		fmt.Println()
 	}
 
@@ -370,15 +370,18 @@ func appBuildRun(cmd *cobra.Command, args []string) {
 	}
 
 	if !buildForce {
-		log.Actionf("identifying applications with outstanding builds")
+		fmt.Printf("identifying applications with outstanding builds")
+		if verboseFlag {
+			fmt.Println()
+		}
 		apps = outstandingBuilds(store, apps)
 	}
 
 	if len(apps) == 0 {
 		fmt.Println()
 		term.PrintSep()
-		fmt.Printf("Application build(s) already exist, nothing to build, see 'baur ls -b'.\n" +
-			"If you want to rebuild applications pass '-f' to 'baur build'\n")
+		fmt.Println("Application build(s) already exist, nothing to build, see 'baur ls -b'.\n" +
+			"If you want to rebuild applications pass '-f' to 'baur build'")
 		os.Exit(0)
 	}
 
@@ -397,10 +400,10 @@ func appBuildRun(cmd *cobra.Command, args []string) {
 		uploadWatchFin = make(chan struct{}, 1)
 		go waitPrintUploadStatus(uploader, uploadChan, uploadWatchFin, outputCnt)
 
-		log.Actionf("building and uploading the following applications: \n%s\n",
+		fmt.Printf("building and uploading the following applications:\n%s\n",
 			appsToString(apps))
 	} else {
-		log.Actionf("building the following applications: \n%s\n",
+		fmt.Printf("building the following applications:\n%s\n",
 			appsToString(apps))
 	}
 
@@ -413,28 +416,29 @@ func appBuildRun(cmd *cobra.Command, args []string) {
 		app := bud.App
 
 		if status.Error != nil {
-			log.Fatalf("%s: build failed: %s\n", app.Name, status.Error)
+			log.Fatalf("%s: build failed: %s", app.Name, status.Error)
 		}
 
 		if status.ExitCode != 0 {
 			log.Fatalf("%s: build failed: command (%q) exited with code %d "+
-				"Output: %s\n",
+				"Output: %s",
 				app.Name, status.Job.Command, status.ExitCode, status.Output)
 		}
 
-		log.Actionf("%s: build successful (%.3fs)\n", app.Name, status.StopTs.Sub(status.StartTs).Seconds())
+		fmt.Printf("%s: build successful (%.3fs)\n", app.Name, status.StopTs.Sub(status.StartTs).Seconds())
 		resultAddBuildResult(bud, status)
 
 		for _, ar := range app.Outputs {
 			if !ar.Exists() {
-				log.Fatalf("build output %q of %s did not exist after build\n",
-					ar, app)
+				log.Fatalf("%s: build output %q did not exist after build",
+					app, ar)
 			}
 
 			if buildUpload {
 				uj, err := ar.UploadJob()
 				if err != nil {
-					log.Fatalf("could not get upload job for build output %s: %s", ar, err)
+					log.Fatalf("%s: could not get upload job for build output %s: %s",
+						app, ar, err)
 				}
 
 				uj.SetUserData(&uploadUserData{
@@ -447,30 +451,30 @@ func appBuildRun(cmd *cobra.Command, args []string) {
 			}
 			d, err := ar.Digest()
 			if err != nil {
-				log.Fatalf("%s: could determine input digest of %s: %s\n",
+				log.Fatalf("%s: calculating input digest of %s failed: %s",
 					app.Name, ar, err)
 			}
 
-			log.Actionf("%s: created %s (%s)\n", app.Name, ar, d)
+			fmt.Printf("%s: created %s (%s)\n", app.Name, ar, d)
 		}
 
 	}
 
 	if buildUpload && outputCnt > 0 {
-		log.Actionf("waiting for uploads to finish...\n")
+		fmt.Println("waiting for uploads to finish...")
 		<-uploadWatchFin
 	}
 
 	term.PrintSep()
-	log.Infof("finished in %s\n", time.Since(startTs))
+	fmt.Printf("finished in %s\n", time.Since(startTs))
 }
 
 func mustGetBuildStatus(app *baur.App, storage storage.Storer) (baur.BuildStatus, *storage.Build, string) {
 	var strBuildID string
 
 	status, build, err := baur.GetBuildStatus(storage, app)
 	if err != nil {
-		log.Fatalf("evaluating build status of %s failed: %s\n", app, err)
+		log.Fatalf("%s: evaluating build status of failed: %s", app, err)
 	}
 
 	if build != nil {

command/apps_init.go

@@ -1,6 +1,7 @@
 package command
 
 import (
+	"fmt"
 	"os"
 	"path"
 	"strings"
@@ -58,6 +59,6 @@ func appsInit(cmd *cobra.Command, args []string) {
 		log.Fatalln(err)
 	}
 
-	log.Infof("configuration file for %s was written to %s\n",
+	fmt.Printf("configuration file for %s was written to %s\n",
 		appName, baur.AppCfgFile)
 }

command/builds_verify.go

@@ -62,7 +62,7 @@ func verify(cmd *cobra.Command, args []string) {
 	const dateLayout = "2006.01.02"
 	startTs, err := time.Parse(dateLayout, verifyFromDate)
 	if err != nil {
-		log.Fatalf("parsing start date value failed: %s\n:", err)
+		log.Fatalf("parsing start date value failed: %s:", err)
 	}
 	repo := MustFindRepository()
 
@@ -78,7 +78,7 @@ func verify(cmd *cobra.Command, args []string) {
 		log.Fatalln("retrieving applications from storage failed:", err)
 	}
 
-	log.Actionf("scanning for builds after %s with same inputs that produced different outputs...\n", startTs.Format(dateLayout))
+	fmt.Printf("scanning for builds after %s with same inputs that produced different outputs...\n", startTs.Format(dateLayout))
 
 	var issuesFound bool
 	for _, app := range storedApps {

command/helpers.go

@@ -28,14 +28,14 @@ func MustFindRepository() *baur.Repository {
 	if err != nil {
 		if os.IsNotExist(err) {
 			log.Fatalf("could not find repository root config file "+
-				"ensure the file '%s' exist in the root\n",
+				"ensure the file '%s' exist in the root",
 				baur.RepositoryCfgFile)
 		}
 
 		log.Fatalln(err)
 	}
 
-	log.Debugf("repository root found: %v\n", rep.Path)
+	log.Debugf("repository root found: %s", rep.Path)
 
 	return rep
 }
@@ -54,7 +54,7 @@ func mustArgToApp(repo *baur.Repository, arg string) *baur.App {
 	if isAppDir(arg) {
 		app, err := repo.AppByDir(arg)
 		if err != nil {
-			log.Fatalf("could not find application in dir '%s': %s\n", arg, err)
+			log.Fatalf("could not find application in dir '%s': %s", arg, err)
 		}
 
 		return app
@@ -63,7 +63,7 @@ func mustArgToApp(repo *baur.Repository, arg string) *baur.App {
 	app, err := repo.AppByName(arg)
 	if err != nil {
 		if os.IsNotExist(err) {
-			log.Fatalf("could not find application with name '%s'\n", arg)
+			log.Fatalf("could not find application with name '%s'", arg)
 		}
 		log.Fatalln(err)
 	}
@@ -75,7 +75,7 @@ func mustArgToApp(repo *baur.Repository, arg string) *baur.App {
 func MustGetPostgresClt(r *baur.Repository) *postgres.Client {
 	clt, err := postgres.New(r.PSQLURL)
 	if err != nil {
-		log.Fatalf("could not establish connection to postgreSQL db: %s\n", err)
+		log.Fatalf("could not establish connection to postgreSQL db: %s", err)
 	}
 
 	return clt
@@ -119,7 +119,7 @@ func mustArgToApps(repo *baur.Repository, args []string) []*baur.App {
 		}
 
 		if len(apps) == 0 {
-			log.Fatalf("could not find any applications\n"+
+			log.Fatalf("could not find any applications"+
 				"- ensure the [Discover] section is correct in %s\n"+
 				"- ensure that you have >1 application dirs "+
 				"containing a %s file\n",

command/inputs_show.go

@@ -50,7 +50,7 @@ func inputsShow(cmd *cobra.Command, args []string) {
 	writeHeaders := !inputsShowConfig.quiet && !inputsShowConfig.csv
 
 	if len(app.BuildInputPaths) == 0 {
-		log.Fatalf("No build inputs have been configured in the %s file of %s\n", baur.AppCfgFile, app.Name)
+		log.Fatalf("No build inputs are configured in %s of %s", baur.AppCfgFile, app.Name)
 	}
 
 	if writeHeaders {

command/repo_init.go

@@ -1,6 +1,7 @@
 package command
 
 import (
+	"fmt"
 	"os"
 	"path"
 
@@ -24,7 +25,7 @@ var initCmd = &cobra.Command{
 func initRepositoryCfg(cmd *cobra.Command, args []string) {
 	rep, err := baur.FindRepository()
 	if err == nil {
-		log.Fatalf("repository configuration %s already exist\n",
+		log.Fatalf("repository configuration %s already exist",
 			path.Join(rep.Path, baur.RepositoryCfgFile))
 	}
 
@@ -44,6 +45,6 @@ func initRepositoryCfg(cmd *cobra.Command, args []string) {
 		log.Fatalln(err)
 	}
 
-	log.Infof("written example repository configuration to %s\n",
+	fmt.Printf("written example repository configuration to %s\n",
 		baur.RepositoryCfgFile)
 }

command/root.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/spf13/cobra"
 
+	"github.com/simplesurance/baur/exec"
 	"github.com/simplesurance/baur/log"
 	"github.com/simplesurance/baur/version"
 )
@@ -25,7 +26,10 @@ var cpuProfilingFlag bool
 var defCPUProfFile = filepath.Join(os.TempDir(), "baur-cpu.prof")
 
 func initSb(_ *cobra.Command, _ []string) {
-	log.DebugEnabled = verboseFlag
+	if verboseFlag {
+		log.StdLogger.EnableDebug(verboseFlag)
+		exec.SetDebugOutputFn(log.StdLogger.Debugf)
+	}
 
 	if cpuProfilingFlag {
 		cpuProfFile, err := os.Create(defCPUProfFile)
@@ -50,7 +54,7 @@ func Execute() {
 	}
 
 	if cpuProfilingFlag {
-		log.Infof("\ncpu profile written to %q\n", defCPUProfFile)
+		fmt.Printf("\ncpu profile written to %q\n", defCPUProfFile)
 		pprof.StopCPUProfile()
 	}
 }