Merge pull request #202 from asteris-llc/feature/improve-logging-#200

Rework logs to use logrus
asteris-llc · Aug 31, 2016 · 9d38b64 · 9d38b64
2 parents 24d867a + 515f94e
commit 9d38b64
Show file tree

Hide file tree

Showing 56 changed files with 875 additions and 889 deletions.
diff --git a/apply/apply.go b/apply/apply.go
@@ -17,9 +17,9 @@ package apply
 import (
 	"context"
 	"fmt"
-	"log"
 
 	"github.com/asteris-llc/converge/graph"
+	"github.com/asteris-llc/converge/helpers/logging"
 	"github.com/asteris-llc/converge/plan"
 	"github.com/asteris-llc/converge/resource"
 	"github.com/pkg/errors"
@@ -37,6 +37,8 @@ func Apply(ctx context.Context, in *graph.Graph) (*graph.Graph, error) {
 func WithNotify(ctx context.Context, in *graph.Graph, notify *graph.Notifier) (*graph.Graph, error) {
 	var hasErrors error
 
+	logger := logging.GetLogger(ctx).WithField("function", "Apply")
+
 	out, err := in.Transform(
 		ctx,
 		notify.Transform(func(id string, out *graph.Graph) error {
@@ -71,7 +73,7 @@ func WithNotify(ctx context.Context, in *graph.Graph, notify *graph.Notifier) (*
 			var newResult *Result
 
 			if result.Status.HasChanges() {
-				log.Printf("[DEBUG] applying %q\n", id)
+				logger.WithField("id", id).Debug("applying")
 
 				err := result.Task.Apply()
 				if err != nil {

diff --git a/cmd/apply.go b/cmd/apply.go
@@ -18,9 +18,10 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/asteris-llc/converge/graph"
+	"github.com/asteris-llc/converge/helpers/logging"
 	"github.com/asteris-llc/converge/rpc"
 	"github.com/asteris-llc/converge/rpc/pb"
 	"github.com/spf13/cobra"
@@ -44,15 +45,19 @@ real happens.`,
 		defer cancel()
 		GracefulExit(cancel)
 
+		// logging
+		clog := log.WithField("component", "client")
+		ctx = logging.WithLogger(ctx, clog)
+
 		maybeSetToken()
 
 		ssl, err := getSSLConfig(getServerName())
 		if err != nil {
-			log.Fatalf("[FATAL] could not get SSL config: %v", err)
+			clog.WithError(err).Fatal("could not get SSL config")
 		}
 
 		if err := maybeStartSelfHostedRPC(ctx, ssl); err != nil {
-			log.Fatalf("[FATAL] %s\n", err)
+			clog.WithError(err).Fatal("could not start RPC")
 		}
 
 		client, err := getRPCExecutorClient(
@@ -63,14 +68,16 @@ real happens.`,
 			},
 		)
 		if err != nil {
-			log.Fatalf("[FATAL] %s\n", err)
+			clog.WithError(err).Fatal("could not get client")
 		}
 
 		rpcParams := getParamsRPC(cmd)
 
 		// execute files
 		for _, fname := range args {
-			log.Printf("[INFO] applying %s\n", fname)
+			flog := clog.WithField("file", fname)
+
+			flog.Info("applying")
 
 			stream, err := client.Apply(
 				ctx,
@@ -80,15 +87,15 @@ real happens.`,
 				},
 			)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: error getting RPC stream: %s\n", fname, err)
+				flog.WithError(err).Fatal("error getting RPC stream")
 			}
 
 			g := graph.New()
 
 			// get edges
 			edges, err := getMeta(stream)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: %s\n", fname, err)
+				flog.WithError(err).Fatal("error getting RPC metadata")
 			}
 			for _, edge := range edges {
 				g.Connect(edge.Source, edge.Dest)
@@ -98,7 +105,16 @@ real happens.`,
 			err = iterateOverStream(
 				stream,
 				func(resp *pb.StatusResponse) {
-					log.Printf("[INFO] %s: %s %s %s\n", fname, resp.Stage, resp.Id, resp.Run)
+					slog := flog.WithFields(log.Fields{
+						"stage": resp.Stage,
+						"run":   resp.Run,
+						"id":    resp.Id,
+					})
+					if resp.Run == pb.StatusResponse_STARTED {
+						slog.Info("got status")
+					} else {
+						slog.Debug("got status")
+					}
 
 					if resp.Stage == pb.StatusResponse_APPLY && resp.Run == pb.StatusResponse_FINISHED {
 						details := resp.GetDetails()
@@ -109,18 +125,18 @@ real happens.`,
 				},
 			)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not get responses")
 			}
 
 			// validate resulting graph
 			if err := g.Validate(); err != nil {
-				log.Printf("[WARNING] %s: graph is not valid: %s\n", fname, err)
+				flog.WithError(err).Warning("graph is not valid")
 			}
 
 			// print results
 			out, err := getPrinter().Show(ctx, g)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: failed printing results: %s\n", fname, err)
+				flog.WithError(err).Fatal("failed to print results")
 			}
 
 			fmt.Print("\n")

diff --git a/cmd/fmt.go b/cmd/fmt.go
@@ -18,9 +18,9 @@ import (
 	"bytes"
 	"errors"
 	"io/ioutil"
-	"log"
 	"os"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/hashicorp/hcl/hcl/printer"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
@@ -38,29 +38,31 @@ var fmtCmd = &cobra.Command{
 	},
 	Run: func(cmd *cobra.Command, args []string) {
 		for _, fname := range args {
+			flog := log.WithField("file", fname)
+
 			content, err := ioutil.ReadFile(fname)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not read %s\n", fname, err)
+				flog.WithError(err).Fatal("could not read")
 			}
 
 			formatted, err := printer.Format(content)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not format content\n", fname)
+				flog.WithError(err).Fatal("could not format content")
 			}
 
 			if viper.GetBool("check") {
 				if !bytes.Equal(content, formatted) {
-					log.Fatalf("[FATAL] %s: needs formatting\n", fname)
+					flog.Fatal("needs formatting")
 				}
 			} else {
 				stat, err := os.Stat(fname)
 				if err != nil {
-					log.Fatalf("[FATAL] %s: could not stat: %s\n", fname, err)
+					flog.WithError(err).Fatal("could not stat")
 				}
 
 				err = ioutil.WriteFile(fname, formatted, stat.Mode())
 				if err != nil {
-					log.Fatalf("[FATAL] %s: could not write content: %s\n", fname, err)
+					flog.WithError(err).Fatal("could not write content")
 				}
 			}
 		}

diff --git a/cmd/graceful_exit.go b/cmd/graceful_exit.go
@@ -16,9 +16,10 @@ package cmd
 
 import (
 	"context"
-	"log"
 	"os"
 	"os/signal"
+
+	log "github.com/Sirupsen/logrus"
 )
 
 // GracefulExit traps interrupt signals for a graceful exit
@@ -38,10 +39,10 @@ func GracefulExitBlocking(cancel context.CancelFunc) {
 
 		switch interruptCount {
 		case 1:
-			log.Println("[INFO] gracefully shutting down (interrupt again to halt)")
+			log.Info("gracefully shutting down (interrupt again to halt)")
 			cancel()
 		case 2:
-			log.Println("[WARN] hard stop! System may be left in an incomplete state")
+			log.Warn("hard stop! System may be left in an incomplete state")
 			os.Exit(2)
 		}
 	}

diff --git a/cmd/graph.go b/cmd/graph.go
@@ -18,8 +18,8 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/asteris-llc/converge/graph"
 	"github.com/asteris-llc/converge/load"
 	"github.com/asteris-llc/converge/prettyprinters"
@@ -51,25 +51,26 @@ You can pipe the output directly to the 'dot' command, for example:
 		params := getParams(cmd)
 
 		fname := args[0]
+		flog := log.WithField("file", fname)
 
 		ctx, cancel := context.WithCancel(context.Background())
 		GracefulExit(cancel)
 
 		out, err := load.Load(ctx, fname)
 		if err != nil {
-			log.Fatalf("[FATAL] %s: could not parse file: %s\n", fname, err)
+			flog.WithError(err).Fatal("could not parse file")
 		}
 
 		if viper.GetBool("merge-duplicates") {
 			var rendered *graph.Graph
 			rendered, err = render.Render(ctx, out, params)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not render: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not render")
 			}
 
 			out, err = graph.MergeDuplicates(ctx, rendered, graph.SkipModuleAndParams)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not merge duplicates: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not merge duplicates")
 			}
 		}
 
@@ -88,7 +89,7 @@ You can pipe the output directly to the 'dot' command, for example:
 		printer := prettyprinters.New(dotPrinter)
 		dotCode, err := printer.Show(ctx, out)
 		if err != nil {
-			log.Fatalf("[FATAL] %s: could not generate dot output: %s", fname, err)
+			flog.WithError(err).Fatal("could not generate dot output")
 		}
 		fmt.Println(dotCode)
 

diff --git a/cmd/healthcheck.go b/cmd/healthcheck.go
@@ -18,9 +18,9 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 	"os"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/asteris-llc/converge/graph"
 	"github.com/asteris-llc/converge/healthcheck"
 	"github.com/asteris-llc/converge/load"
@@ -48,42 +48,40 @@ not display healthy checks.`,
 		GracefulExit(cancel)
 
 		// params
-		params, err := getParamsFromFlags(cmd.Flags())
-		if err != nil {
-			log.Fatalf("[FATAL] could not read params: %s\n", err)
-		}
+		params := getParams(cmd)
 
 		for _, fname := range args {
-			log.Printf("[INFO] planning %s\n", fname)
+			flog := log.WithField("file", fname)
+			flog.Info("checking health")
 
 			loaded, err := load.Load(ctx, fname)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not parse file: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not parse file")
 			}
 
 			rendered, err := render.Render(ctx, loaded, params)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not render: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not render")
 			}
 
 			merged, err := graph.MergeDuplicates(ctx, rendered, graph.SkipModuleAndParams)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: could not merge duplicates: %s\n", fname, err)
+				flog.WithError(err).Fatal("could not merge duplicates")
 			}
 
 			planned, err := plan.Plan(ctx, merged)
 			if err != nil && err != plan.ErrTreeContainsErrors {
-				log.Fatalf("[FATAL] %s: planning failed: %s\n", fname, err)
+				flog.WithError(err).Fatal("planning failed")
 			}
 
 			results, err := healthcheck.CheckGraph(ctx, planned)
 			if err != nil {
-				log.Fatalf("[FATAL] %s: checking failed: %s\n", fname, err)
+				flog.WithError(err).Fatal("checking failed")
 			}
 
 			out, perr := healthPrinter().Show(ctx, results)
 			if perr != nil {
-				log.Fatalf("[FATAL] %s: failed printing results: %s\n", fname, err)
+				flog.WithError(perr).Fatal("failed printing results")
 			}
 
 			fmt.Print("\n")

diff --git a/cmd/logging.go b/cmd/logging.go