feat: improve logging with logrus (#60)

* fix: users test

* feat: add expired value in permissions

* fix: revert isExpired method changes

* fix: minor fixes

* feat: better logs with logrus

* fix: error logging

* fix: set default log level to error

* Update README.md

Author: bietkul

README.md

@@ -80,39 +80,56 @@ You can build the binary locally by executing the following command from the pro
 
 This produces an executable & plugin libraries in the root project directory. To start the Arc server, run:
 
-    ./build/arc --log=stdout --env=config/manual.env
+    ./build/arc --env=config/manual.env
 
 Alternatively, you could execute the following commands to start the server without producing an executable, (but still produce the plugin libraries):
 
     make plugins
-    go run main.go --log=stdout --env=config/manual.env
+    go run main.go --env=config/manual.env
+
 
 **Note**: Running the executable assumes an active Elasticsearch connection whose url is to be provided in the `.env` file. manual.env configures it to be the localhost.
 
+### Logging
+Define the run time flag (`log`) to change the default log mode, the possible options are:
+
+#### debug
+Most verbose, use this to get logs for elasticsearch interactions.
+#### info
+Prints the basic information
+#### error (default)
+Only log the errors
+
 #### TLS Support
 
 You can optionally start arc to serve https requests instead of http requests using the flag https.
 You also need to provide the server key & certificate file location through the environment file.
 manual.env is configured to use demo server key & certificates, which work for localhost.
+```bash
     go run main.go --log=stdout --env=config/manual.env --https
-
+```
 If you wish to manually test TLS support at localhost,
 curl needs to be also passed an extra parameter providing the cacert, in this case.
+```bash
     curl https://foo:bar@localhost:8000/_user --cacert sample/rootCA.pem
+```
 
 #### JWT Key Loading through HTTP
 
 If you wish to test loading JWT Key through HTTP, you can use the following commands to start a HTTP
 server serving the key
+```bash
     cd sample
     python -m SimpleHTTPServer 8500
-
+```
 Then start arc using the command:
+```bash
     go run main.go --log=stdout --env=config/manual-http-jwt.env
+```
 
 #### Run Tests
 
-Currently, tests are WIP and implemented for auth and logs modules. You can run tests using:
+Currently, tests are WIP and implemented for auth, permissions and users modules. You can run tests using:
 
     go test ./...
 

go.mod

@@ -13,6 +13,8 @@ require (
 	github.com/robfig/cron v1.1.0
 	github.com/rogpeppe/go-internal v1.2.2 // indirect
 	github.com/rs/cors v1.6.0
+	github.com/siddharthlatest/mustache v0.0.0-20160118163553-00029677272d
+	github.com/sirupsen/logrus v1.4.2
 	github.com/smartystreets/goconvey v1.6.4
 	github.com/ulule/limiter v2.2.0+incompatible
 	golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2

go.sum

@@ -355,11 +355,14 @@ github.com/shurcooL/highlight_diff v0.0.0-20170515013008-09bb4053de1b/go.mod h1:
 github.com/shurcooL/highlight_go v0.0.0-20170515013102-78fb10f4a5f8/go.mod h1:UDKB5a1T23gOMUJrI+uSuH0VRDStOiUVSjBTRDVBVag=
 github.com/shurcooL/octicon v0.0.0-20180602230221-c42b0e3b24d9/go.mod h1:eWdoE5JD4R5UVWDucdOPg1g2fqQRq78IQa9zlOV1vpQ=
 github.com/shurcooL/sanitized_anchor_name v0.0.0-20170918181015-86672fcb3f95/go.mod h1:1NzhyTcUVG4SuEtjjoZeVRXNmyL/1OwPU0+IJeTBvfc=
+github.com/siddharthlatest/mustache v0.0.0-20160118163553-00029677272d/go.mod h1:ej02m5sGsrB5WBnM5xLGTfxUInBAbfNFPAsoJxBjn50=
 github.com/sirupsen/logrus v1.0.6/go.mod h1:pMByvHTf9Beacp5x1UXfOR9xyW/9antXMhjMPG0dEzc=
 github.com/sirupsen/logrus v1.1.0/go.mod h1:zrgwTnHtNr00buQ1vSptGe8m1f/BbgsPukg8qsT7A+A=
 github.com/sirupsen/logrus v1.1.1/go.mod h1:zrgwTnHtNr00buQ1vSptGe8m1f/BbgsPukg8qsT7A+A=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/sirupsen/logrus v1.3.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
+github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
+github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d h1:zE9ykElWQ6/NYmHa3jpm/yHnI4xSofP+UP6SpjHcSeM=
 github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
 github.com/smartystreets/go-aws-auth v0.0.0-20180515143844-0c1422d1fdb9/go.mod h1:SnhjPscd9TpLiy1LpzGSKh3bXCfxxXuqd9xmQJy3slM=
@@ -459,6 +462,7 @@ golang.org/x/sys v0.0.0-20190102155601-82a175fd1598/go.mod h1:STP8DvDyc/dI5b8T5h
 golang.org/x/sys v0.0.0-20190116161447-11f53e031339/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191008105621-543471e840be h1:QAcqgptGM8IQBC9K/RC4o+O9YmqEm0diQn9QmZw/0mU=
 golang.org/x/sys v0.0.0-20191008105621-543471e840be/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

main.go

@@ -5,8 +5,6 @@ import (
 	"flag"
 	"fmt"
 	"io"
-	"io/ioutil"
-	"log"
 	"net/http"
 	"os"
 	"path/filepath"
@@ -22,14 +20,14 @@ import (
 	"github.com/robfig/cron"
 	"github.com/rs/cors"
 
-	"gopkg.in/natefinch/lumberjack.v2"
+	log "github.com/sirupsen/logrus"
 )
 
 const logTag = "[cmd]"
 
 var (
 	envFile     string
-	logFile     string
+	logMode     string
 	listPlugins bool
 	address     string
 	port        int
@@ -49,7 +47,7 @@ var (
 
 func init() {
 	flag.StringVar(&envFile, "env", ".env", "Path to file with environment variables to load in KEY=VALUE format")
-	flag.StringVar(&logFile, "log", "", "Process log file")
+	flag.StringVar(&logMode, "log", "", "Process log file")
 	flag.BoolVar(&listPlugins, "plugins", false, "List currently registered plugins")
 	flag.StringVar(&address, "addr", "", "Address to serve on")
 	flag.IntVar(&port, "port", 8000, "Port number")
@@ -60,26 +58,23 @@ func init() {
 func main() {
 	flag.Parse()
 
-	log.SetFlags(log.LstdFlags | log.Lshortfile)
-	switch logFile {
-	case "stdout":
-		log.SetOutput(os.Stdout)
-	case "stderr":
-		log.SetOutput(os.Stderr)
-	case "":
-		log.SetOutput(ioutil.Discard)
+	log.SetFormatter(&log.TextFormatter{
+		FullTimestamp:   true,
+		TimestampFormat: "2006/01/02 15:04:05",
+	})
+
+	switch logMode {
+	case "debug":
+		log.SetLevel(log.DebugLevel)
+	case "info":
+		log.SetLevel(log.InfoLevel)
 	default:
-		log.SetOutput(&lumberjack.Logger{
-			Filename:   logFile,
-			MaxSize:    100,
-			MaxAge:     14,
-			MaxBackups: 10,
-		})
+		log.SetLevel(log.ErrorLevel)
 	}
 
 	// Load all env vars from envFile
 	if err := LoadEnvFromFile(envFile); err != nil {
-		log.Printf("%s: reading env file %q: %v", logTag, envFile, err)
+		log.Error(logTag, ": reading env file", envFile, ": ", err)
 	}
 
 	router := mux.NewRouter().StrictSlash(true)
@@ -89,7 +84,7 @@ func main() {
 	} else {
 		_, err := strconv.Atoi(PlanRefreshInterval)
 		if err != nil {
-			log.Fatal("PLAN_REFRESH_INTERVAL must be an integer")
+			log.Fatal("PLAN_REFRESH_INTERVAL must be an integer: ", err)
 		}
 	}
 

middleware/interceptor/interceptor.go

@@ -1,11 +1,12 @@
 package interceptor
 
 import (
-	"log"
 	"net/http"
 	"net/url"
 	"os"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/appbaseio/arc/errors"
 	"github.com/appbaseio/arc/middleware"
 	"github.com/appbaseio/arc/util"
@@ -26,12 +27,12 @@ func redirect(h http.HandlerFunc) http.HandlerFunc {
 		rawURL := os.Getenv("ES_CLUSTER_URL")
 		if rawURL == "" {
 			err := errors.NewEnvVarNotSetError(envEsClusterURL)
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			return
 		}
 		esURL, err := url.Parse(rawURL)
 		if err != nil {
-			log.Printf("%s: error parsing %s=%s: %v", logTag, rawURL, envEsClusterURL, err)
+			log.Error(logTag, ": error parsing ", rawURL, "=", envEsClusterURL, ": ", err)
 			return
 		}
 
@@ -41,7 +42,7 @@ func redirect(h http.HandlerFunc) http.HandlerFunc {
 
 		req, err := redirectRequest(r)
 		if err != nil {
-			log.Printf("%s: %v\n", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, err.Error(), http.StatusInternalServerError)
 			return
 		}

middleware/logger/logger.go

@@ -2,7 +2,7 @@ package logger
 
 import (
 	"fmt"
-	"log"
+	log "github.com/sirupsen/logrus"
 	"net/http"
 	"strings"
 	"time"

middleware/ratelimiter/ratelimiter.go

@@ -3,11 +3,12 @@ package ratelimiter
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 	"sync"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/appbaseio/arc/middleware"
 	"github.com/appbaseio/arc/model/category"
 	"github.com/appbaseio/arc/model/credential"
@@ -60,7 +61,7 @@ func (rl *Ratelimiter) rateLimit(h http.HandlerFunc) http.HandlerFunc {
 
 		reqCredential, err := credential.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v\n", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, err.Error(), http.StatusInternalServerError)
 			return
 		}
@@ -70,14 +71,14 @@ func (rl *Ratelimiter) rateLimit(h http.HandlerFunc) http.HandlerFunc {
 			errMsg := "An error occurred while validating rate limit"
 			reqPermission, err := permission.FromContext(ctx)
 			if err != nil {
-				log.Printf("%s: %v", logTag, err)
+				log.Error(logTag, ": ", err)
 				util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 				return
 			}
 
 			reqCategory, err := category.FromContext(ctx)
 			if err != nil {
-				log.Printf("%s: %v", logTag, err)
+				log.Error(logTag, ": ", err)
 				util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 				return
 			}

middleware/validate/acl.go

@@ -3,9 +3,10 @@ package validate
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/appbaseio/arc/middleware"
 	"github.com/appbaseio/arc/model/acl"
 	"github.com/appbaseio/arc/model/credential"
@@ -26,21 +27,21 @@ func validateACL(h http.HandlerFunc) http.HandlerFunc {
 		errMsg := "an error occurred while validating request acl"
 		reqACL, err := acl.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}
 
 		reqCredential, err := credential.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}
 
 		ok, err := hasACL(ctx, reqCredential, reqACL)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}

middleware/validate/category.go

@@ -3,9 +3,10 @@ package validate
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/appbaseio/arc/middleware"
 	"github.com/appbaseio/arc/model/category"
 	"github.com/appbaseio/arc/model/credential"
@@ -26,21 +27,21 @@ func validateCategory(h http.HandlerFunc) http.HandlerFunc {
 		errMsg := "an error occurred while validating request category"
 		reqCategory, err := category.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}
 
 		reqCredential, err := credential.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}
 
 		ok, err := hasCategory(ctx, reqCredential, reqCategory)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, errMsg, http.StatusInternalServerError)
 			return
 		}

middleware/validate/expiry.go

@@ -2,9 +2,10 @@ package validate
 
 import (
 	"fmt"
-	"log"
 	"net/http"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/appbaseio/arc/middleware"
 	"github.com/appbaseio/arc/model/credential"
 	"github.com/appbaseio/arc/model/permission"
@@ -22,22 +23,22 @@ func validateExpiry(h http.HandlerFunc) http.HandlerFunc {
 
 		reqCredential, err := credential.FromContext(ctx)
 		if err != nil {
-			log.Printf("%s: %v", logTag, err)
+			log.Error(logTag, ": ", err)
 			util.WriteBackError(w, err.Error(), http.StatusInternalServerError)
 			return
 		}
 
 		if reqCredential == credential.Permission {
 			reqPermission, err := permission.FromContext(ctx)
 			if err != nil {
-				log.Printf("%s: %v", logTag, err)
+				log.Error(logTag, ": ", err)
 				util.WriteBackError(w, err.Error(), http.StatusInternalServerError)
 				return
 			}
 
 			expired, err := reqPermission.IsExpired()
 			if err != nil {
-				log.Printf("%s: %v", logTag, err)
+				log.Error(logTag, ": ", err)
 				util.WriteBackError(w, err.Error(), http.StatusInternalServerError)
 				return
 			}