[logs] Log as JSON with Logrus (#4)

config.go

@@ -1,9 +1,10 @@
 package main
 
 import (
-	"fmt"
 	"os"
 	"strings"
+
+	log "github.com/sirupsen/logrus"
 )
 
 type Config struct {
@@ -17,17 +18,11 @@ type Config struct {
 	GenericQuitEndpoints    []string
 }
 
-func log(message string) {
-	if config.LoggingEnabled {
-		println("envoy-preflight: " + message)
-	}
-}
-
 func getConfig() Config {
 	loggingEnabled := getBoolFromEnv("ENVOY_PREFLIGHT_LOGGING", true, false)
 
 	if getStringFromEnv("ENVOY_KILL_API", "", false) != "" {
-		log("Warning: don't use ENVOY_KILL_API but ISTIO_QUIT_API instead")
+		log.Error("don't use ENVOY_KILL_API but ISTIO_QUIT_API instead")
 	}
 
 	defaultEnvoyAdminAPI := ""
@@ -61,7 +56,7 @@ func getStringArrayFromEnv(name string, defaultVal []string, logEnabled bool) []
 	}
 
 	if logEnabled {
-		log(fmt.Sprintf("%s: %s", name, userValCsv))
+		log.Infof("%s: %s", name, userValCsv)
 	}
 
 	userValArray := strings.Split(userValCsv, ",")
@@ -75,7 +70,7 @@ func getStringArrayFromEnv(name string, defaultVal []string, logEnabled bool) []
 func getStringFromEnv(name string, defaultVal string, logEnabled bool) string {
 	userVal := os.Getenv(name)
 	if logEnabled {
-		log(fmt.Sprintf("%s: %s", name, userVal))
+		log.Infof("%s: %s", name, userVal)
 	}
 	if userVal != "" {
 		return userVal
@@ -93,14 +88,14 @@ func getBoolFromEnv(name string, defaultVal bool, logEnabled bool) bool {
 	// User set something, check it is valid
 	if userVal != "true" && userVal != "false" {
 		if logEnabled {
-			log(fmt.Sprintf("%s: %s (Invalid value will be ignored)", name, userVal))
+			log.Infof("%s: %s (Invalid value will be ignored)", name, userVal)
 		}
 		return defaultVal
 	}
 
 	// User gave valid option
 	if logEnabled {
-		log(fmt.Sprintf("%s: %s", name, userVal))
+		log.Infof("%s: %s", name, userVal)
 	}
 	return (userVal == "true")
 }

go.mod

@@ -12,6 +12,7 @@ require (
 	github.com/monzo/terrors v0.0.0-20181205142146-d977e210f156 // indirect
 	github.com/monzo/typhon v0.0.0-20190413083455-45c89a830a76
 	github.com/nu7hatch/gouuid v0.0.0-20131221200532-179d4d0c4d8d // indirect
+	github.com/sirupsen/logrus v1.8.1
 	github.com/stretchr/testify v1.4.0 // indirect
 	golang.org/x/net v0.0.0-20190415214537-1da14a5a36f2 // indirect
 )

go.sum

@@ -2,8 +2,9 @@ github.com/cenk/backoff v2.1.1+incompatible h1:gaShhlJc32b7ht9cwld/ti0z7tJOf69oU
 github.com/cenk/backoff v2.1.1+incompatible/go.mod h1:7FtoeaSnHoZnmZzz47cM35Y9nSW7tNyaidugnHTaFDE=
 github.com/cihub/seelog v0.0.0-20151216151435-d2c6e5aa9fbf h1:XI2tOTCBqEnMyN2j1yPBI07yQHeywUSCEf8YWqf0oKw=
 github.com/cihub/seelog v0.0.0-20151216151435-d2c6e5aa9fbf/go.mod h1:9d6lWj8KzO/fd/NrVaLscBKmPigpZpn5YawRPw+e3Yo=
-github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/deckarep/golang-set v1.7.1 h1:SCQV0S6gTtp6itiFrTqI+pfmJ4LN85S1YzhDf9rTHJQ=
 github.com/deckarep/golang-set v1.7.1/go.mod h1:93vsz/8Wt4joVM7c2AVqh+YRMiUSc14yDtF28KmMOgQ=
 github.com/fortytw2/leaktest v1.3.0 h1:u8491cBMTQ8ft8aeV+adlcytMZylmA5nnwwkRZjI8vw=
@@ -20,13 +21,18 @@ github.com/nu7hatch/gouuid v0.0.0-20131221200532-179d4d0c4d8d h1:VhgPp6v9qf9Agr/
 github.com/nu7hatch/gouuid v0.0.0-20131221200532-179d4d0c4d8d/go.mod h1:YUTz3bUH2ZwIWBy3CJBeOBEugqcmXREj14T+iG/4k4U=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE=
+github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/net v0.0.0-20190415214537-1da14a5a36f2 h1:iC0Y6EDq+rhnAePxGvJs2kzUAYcwESqdcGRPzEUfzTU=
 golang.org/x/net v0.0.0-20190415214537-1da14a5a36f2/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037 h1:YyJpGZS1sBuBCzLAR1VEpK193GlqGZbnPFnPV/5Rsb4=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=

main.go

@@ -9,6 +9,8 @@ import (
 	"os/signal"
 	"strings"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/cenk/backoff"
 	"github.com/monzo/typhon"
 )
@@ -22,27 +24,29 @@ var (
 )
 
 func main() {
+	log.SetFormatter(&log.JSONFormatter{})
 	config = getConfig()
 
 	// Check if logging is enabled
 	if config.LoggingEnabled {
-		log("Logging is now enabled")
+		log.Debug("logging is now enabled")
 	}
 
 	// If an envoy API was set and config is set to wait on envoy
 	if config.EnvoyAdminAPI != "" && config.StartWithoutEnvoy == false {
-		log("Blocking until envoy starts")
+		log.Info("blocking until envoy starts")
 		block()
 	}
 
 	if len(os.Args) < 2 {
-		log("No arguments received, exiting")
+		log.Info("no arguments received, exiting")
 		return
 	}
 
 	binary, err := exec.LookPath(os.Args[1])
 	if err != nil {
-		panic(err)
+		log.Error(err.Error())
+		os.Exit(1)
 	}
 
 	var proc *os.Process
@@ -56,7 +60,7 @@ func main() {
 				proc.Signal(sig)
 			} else {
 				// Signal received before the process even started. Let's just exit.
-				log("Received exit signal, exiting")
+				log.Info("received exit signal, exiting")
 				os.Exit(1)
 			}
 		}
@@ -67,12 +71,14 @@ func main() {
 		Files: []*os.File{os.Stdin, os.Stdout, os.Stderr},
 	})
 	if err != nil {
-		panic(err)
+		log.Error(err.Error())
+		os.Exit(1)
 	}
 
 	state, err := proc.Wait()
 	if err != nil {
-		panic(err)
+		log.Error(err.Error())
+		os.Exit(1)
 	}
 
 	exitCode := state.ExitCode()
@@ -86,15 +92,15 @@ func kill(exitCode int) {
 	switch {
 	case config.EnvoyAdminAPI == "":
 		// We don't have an ENVOY_ADMIN_API env var, do nothing
-		log("No ENVOY_ADMIN_API, doing nothing")
+		log.Info("no ENVOY_ADMIN_API, doing nothing")
 	case !strings.Contains(config.EnvoyAdminAPI, "127.0.0.1") && !strings.Contains(config.EnvoyAdminAPI, "localhost"):
 		// Envoy is not local; do nothing
-		log("ENVOY_ADMIN_API is not localhost or 127.0.0.1, doing nothing")
+		log.Info("ENVOY_ADMIN_API is not localhost or 127.0.0.1, doing nothing")
 	case config.NeverKillIstio:
 		// We're configured never to kill envoy, do nothing
-		log("NEVER_KILL_ISTIO is true, doing nothing")
+		log.Info("NEVER_KILL_ISTIO is true, doing nothing")
 	case config.NeverKillIstioOnFailure && exitCode != 0:
-		log("NEVER_KILL_ISTIO_ON_FAILURE is true, exiting without killing Istio")
+		log.Info("NEVER_KILL_ISTIO_ON_FAILURE is true, exiting without killing Istio")
 	case config.IstioQuitAPI == "":
 		// No istio API sent, fallback to Pkill method
 		killGenericEndpoints()
@@ -115,36 +121,35 @@ func killGenericEndpoints() {
 		genericEndpoint = strings.Trim(genericEndpoint, " ")
 		resp := typhon.NewRequest(context.Background(), "POST", genericEndpoint, nil).Send().Response()
 		if resp.Error != nil {
-			log(fmt.Sprintf("Sent POST to '%s', error: %s", genericEndpoint, resp.Error))
+			log.Errorf("sent POST to '%s', error: %s", genericEndpoint, resp.Error)
 			continue
 		}
-		log(fmt.Sprintf("Sent POST to '%s', status code: %d", genericEndpoint, resp.StatusCode))
+		log.Infof("sent POST to '%s', status code: %v", genericEndpoint, resp.StatusCode)
 	}
 }
 
 func killIstioWithAPI() {
-	log(fmt.Sprintf("Stopping  Istio using Istio API '%s' (intended for Istio >v1.2)", config.IstioQuitAPI))
+	log.Infof("stopping  Istio using Istio API '%s' (intended for Istio >v1.2)", config.IstioQuitAPI)
 
 	url := fmt.Sprintf("%s/quitquitquit", config.IstioQuitAPI)
 	resp := typhon.NewRequest(context.Background(), "POST", url, nil).Send().Response()
-	log(fmt.Sprintf("Sent quitquitquit to Istio, status code: %d", resp.StatusCode))
+	log.Infof("sent quitquitquit to Istio, status code: %d", resp.StatusCode)
 
 	if resp.StatusCode != 200 && config.IstioFallbackPkill {
-		log(fmt.Sprintf("quitquitquit failed, will attempt pkill method"))
+		log.Error("quitquitquit failed, will attempt pkill method")
 		killIstioWithPkill()
 	}
 }
 
 func killIstioWithPkill() {
-	log("Stopping Istio using pkill command (intended for Istio <v1.3)")
-
+	log.Info("stopping Istio using pkill command (intended for Istio <v1.3)")
 	cmd := exec.Command("sh", "-c", "pkill -SIGINT pilot-agent")
 	_, err := cmd.Output()
 	if err == nil {
-		log("Process pilot-agent successfully stopped")
+		log.Info("process pilot-agent successfully stopped")
 	} else {
 		errorMessage := err.Error()
-		log("pilot-agent could not be stopped, err: " + errorMessage)
+		log.Errorf("pilot-agent could not be stopped, err: " + errorMessage)
 	}
 }