feat(): add custom logger

main.go

@@ -1,29 +1,133 @@
 package main
 
 import (
+	"context"
 	"flag"
+	"fmt"
 	"log"
 	"net/http"
+	"os"
+	"os/signal"
+	"sync/atomic"
+	"time"
 
 	"github.com/ncarlier/webhookd/pkg/api"
+	"github.com/ncarlier/webhookd/pkg/logger"
 	"github.com/ncarlier/webhookd/pkg/worker"
 )
 
+type key int
+
+const (
+	requestIDKey key = 0
+)
+
 var (
-	lAddr     = flag.String("l", ":8080", "HTTP service address (e.g.address, ':8080')")
+	healthy int32
-	nbWorkers = flag.Int("n", 2, "The number of workers to start")
+)
+
+var (
+	listenAddr = flag.String("l", ":8080", "HTTP service address (e.g.address, ':8080')")
+	nbWorkers  = flag.Int("n", 2, "The number of workers to start")
+	debug      = flag.Bool("d", false, "Output debug logs")
 )
 
 func main() {
 	flag.Parse()
 
-	log.Println("Starting webhookd server...")
+	level := "info"
+	if *debug {
+		level = "debug"
+	}
+	logger.Init(level)
+
+	logger.Debug.Println("Starting webhookd server...")
+
+	router := http.NewServeMux()
+	router.Handle("/", api.Index())
+	router.Handle("/healthz", healthz())
+
+	nextRequestID := func() string {
+		return fmt.Sprintf("%d", time.Now().UnixNano())
+	}
+
+	server := &http.Server{
+		Addr:         *listenAddr,
+		Handler:      tracing(nextRequestID)(logging(logger.Debug)(router)),
+		ErrorLog:     logger.Error,
+		ReadTimeout:  5 * time.Second,
+		WriteTimeout: 10 * time.Second,
+		IdleTimeout:  15 * time.Second,
+	}
 
 	// Start the dispatcher.
-	log.Printf("Starting the dispatcher (%d workers)...\n", *nbWorkers)
+	logger.Debug.Printf("Starting the dispatcher (%d workers)...\n", *nbWorkers)
 	worker.StartDispatcher(*nbWorkers)
 
-	log.Printf("Starting the http server (%s)\n", *lAddr)
+	done := make(chan bool)
-	http.HandleFunc("/", api.WebhookHandler)
+	quit := make(chan os.Signal, 1)
-	log.Fatal(http.ListenAndServe(*lAddr, nil))
+	signal.Notify(quit, os.Interrupt)
+
+	go func() {
+		<-quit
+		logger.Debug.Println("Server is shutting down...")
+		atomic.StoreInt32(&healthy, 0)
+
+		ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
+		defer cancel()
+
+		server.SetKeepAlivesEnabled(false)
+		if err := server.Shutdown(ctx); err != nil {
+			logger.Error.Fatalf("Could not gracefully shutdown the server: %v\n", err)
+		}
+		close(done)
+	}()
+
+	logger.Info.Println("Server is ready to handle requests at", *listenAddr)
+	atomic.StoreInt32(&healthy, 1)
+	if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed {
+		logger.Error.Fatalf("Could not listen on %s: %v\n", *listenAddr, err)
+	}
+
+	<-done
+	logger.Debug.Println("Server stopped")
+}
+
+func healthz() http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		if atomic.LoadInt32(&healthy) == 1 {
+			w.WriteHeader(http.StatusNoContent)
+			return
+		}
+		w.WriteHeader(http.StatusServiceUnavailable)
+	})
+}
+
+func logging(logger *log.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			defer func() {
+				requestID, ok := r.Context().Value(requestIDKey).(string)
+				if !ok {
+					requestID = "unknown"
+				}
+				logger.Println(requestID, r.Method, r.URL.Path, r.RemoteAddr, r.UserAgent())
+			}()
+			next.ServeHTTP(w, r)
+		})
+	}
+}
+
+func tracing(nextRequestID func() string) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			requestID := r.Header.Get("X-Request-Id")
+			if requestID == "" {
+				requestID = nextRequestID()
+			}
+			ctx := context.WithValue(r.Context(), requestIDKey, requestID)
+			w.Header().Set("X-Request-Id", requestID)
+			next.ServeHTTP(w, r.WithContext(ctx))
+		})
+	}
 }

pkg/hook/script.go

@@ -3,9 +3,10 @@ package hook
 import (
 	"errors"
 	"fmt"
-	"log"
 	"os"
 	"path"
+
+	"github.com/ncarlier/webhookd/pkg/logger"
 )
 
 var (
@@ -19,7 +20,7 @@ func ResolveScript(p string) (string, error) {
 	}
 
 	script := path.Join(scriptsdir, fmt.Sprintf("%s.sh", p))
-	log.Println("Resolving script: ", script, "...")
+	logger.Debug.Println("Resolving script: ", script, "...")
 	if _, err := os.Stat(script); os.IsNotExist(err) {
 		return "", errors.New("Script not found: " + script)
 	}

pkg/logger/main.go

@@ -0,0 +1,44 @@
+package logger
+
+import (
+	"io"
+	"io/ioutil"
+	"log"
+	"os"
+)
+
+var (
+	// Debug level
+	Debug *log.Logger
+	// Info level
+	Info *log.Logger
+	// Warning level
+	Warning *log.Logger
+	// Error level
+	Error *log.Logger
+)
+
+// Init logger level
+func Init(level string) {
+	var debugHandle, infoHandle, warnHandle, errorHandle io.Writer
+	debugHandle = os.Stdout
+	infoHandle = os.Stdout
+	warnHandle = os.Stderr
+	errorHandle = os.Stderr
+	switch level {
+	case "info":
+		debugHandle = ioutil.Discard
+	case "warn":
+		debugHandle = ioutil.Discard
+		infoHandle = ioutil.Discard
+	case "error":
+		debugHandle = ioutil.Discard
+		infoHandle = ioutil.Discard
+		warnHandle = ioutil.Discard
+	}
+
+	Debug = log.New(debugHandle, "DEBUG: ", log.Ldate|log.Ltime|log.Lshortfile)
+	Info = log.New(infoHandle, "INFO: ", log.Ldate|log.Ltime|log.Lshortfile)
+	Warning = log.New(warnHandle, "WARNING: ", log.Ldate|log.Ltime|log.Lshortfile)
+	Error = log.New(errorHandle, "ERROR: ", log.Ldate|log.Ltime|log.Lshortfile)
+}

pkg/notification/http_notifier.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"fmt"
 	"io"
-	"log"
 	"mime/multipart"
 	"net/http"
 	"net/textproto"
@@ -12,6 +11,8 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
+
+	"github.com/ncarlier/webhookd/pkg/logger"
 )
 
 // HTTPNotifier is able to send a notification to a HTTP endpoint.
@@ -26,7 +27,7 @@ func newHTTPNotifier() *HTTPNotifier {
 	notifier := new(HTTPNotifier)
 	notifier.URL = os.Getenv("APP_HTTP_NOTIFIER_URL")
 	if notifier.URL == "" {
-		log.Println("Unable to create HTTP notifier. APP_HTTP_NOTIFIER_URL not set.")
+		logger.Error.Println("Unable to create HTTP notifier. APP_HTTP_NOTIFIER_URL not set.")
 		return nil
 	}
 	user := os.Getenv("APP_HTTP_NOTIFIER_USER")
@@ -46,7 +47,7 @@ func newHTTPNotifier() *HTTPNotifier {
 
 // Notify send a notification to a HTTP endpoint.
 func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
-	log.Println("Sending notification '" + subject + "' to " + n.URL + " ...")
+	logger.Debug.Println("Sending notification '" + subject + "' to " + n.URL + " ...")
 	data := make(url.Values)
 	data.Set("from", n.From)
 	data.Set("to", n.To)
@@ -56,7 +57,7 @@ func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
 	if attachfile != "" {
 		file, err := os.Open(attachfile)
 		if err != nil {
-			log.Println(err)
+			logger.Error.Println("Unable to open notification attachment file", err)
 			return
 		}
 		defer file.Close()
@@ -69,7 +70,7 @@ func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
 		mh.Set("Content-Disposition", fmt.Sprintf("form-data; name=\"attachment\"; filename=\"%s\"", filepath.Base(attachfile)))
 		part, err := writer.CreatePart(mh)
 		if err != nil {
-			log.Println("Unable to create for file", err)
+			logger.Error.Println("Unable to create HTTP notification attachment", err)
 			return
 		}
 		_, err = io.Copy(part, file)
@@ -80,12 +81,12 @@ func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
 
 		err = writer.Close()
 		if err != nil {
-			log.Println("Unable to close the gzip writer", err)
+			logger.Error.Println("Unable to close the gzip writer", err)
 			return
 		}
 		req, err := http.NewRequest("POST", n.URL, body)
 		if err != nil {
-			log.Println("Unable to post request", err)
+			logger.Error.Println("Unable to post HTTP notification", err)
 		}
 		defer req.Body.Close()
 		req.Header.Set("Content-Type", writer.FormDataContentType())
@@ -98,21 +99,21 @@ func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
 		client := &http.Client{}
 		res, err := client.Do(req)
 		if err != nil {
-			log.Println("Unable to do the request", err)
+			logger.Error.Println("Unable to do HTTP notification request", err)
 			return
 		}
 
 		// Check the response
 		if res.StatusCode != http.StatusOK {
-			log.Println("bad status: ", res.Status)
+			logger.Error.Println("HTTP notification bad response: ", res.Status)
-			log.Println(res.Body)
+			logger.Debug.Println(res.Body)
 			return
 		}
-		log.Println("HTTP notification sended with attachment: ", attachfile)
+		logger.Info.Println("HTTP notification sent with attachment: ", attachfile)
 	} else {
 		req, err := http.NewRequest("POST", n.URL, bytes.NewBufferString(data.Encode()))
 		if err != nil {
-			log.Println("Unable to post request", err)
+			logger.Error.Println("Unable to post HTTP notification request", err)
 		}
 		defer req.Body.Close()
 
@@ -124,16 +125,16 @@ func (n *HTTPNotifier) Notify(subject string, text string, attachfile string) {
 		client := &http.Client{}
 		res, err := client.Do(req)
 		if err != nil {
-			log.Println("Unable to do the request", err)
+			logger.Error.Println("Unable to do the HTTP notification request", err)
 			return
 		}
 
 		// Check the response
 		if res.StatusCode != http.StatusOK {
-			log.Println("bad status: ", res.Status)
+			logger.Error.Println("HTTP notification bad response: ", res.Status)
-			log.Println(res.Body)
+			logger.Debug.Println(res.Body)
 			return
 		}
-		log.Println("HTTP notification sended.")
+		logger.Info.Println("HTTP notification sent.")
 	}
 }

pkg/notification/smtp_notifier.go

@@ -5,6 +5,8 @@ import (
 	"log"
 	"net/smtp"
 	"os"
+
+	"github.com/ncarlier/webhookd/pkg/logger"
 )
 
 // SMTPNotifier is able to send notifcation to a email destination.
@@ -33,7 +35,7 @@ func newSMTPNotifier() *SMTPNotifier {
 
 // Notify send a notification to a email destination.
 func (n *SMTPNotifier) Notify(subject string, text string, attachfile string) {
-	log.Println("SMTP notification: ", subject)
+	logger.Debug.Println("SMTP notification: ", subject)
 	// Connect to the remote SMTP server.
 	c, err := smtp.Dial(n.Host)
 	if err != nil {

pkg/tools/compress.go

@@ -4,8 +4,9 @@ import (
 	"bufio"
 	"compress/gzip"
 	"fmt"
-	"log"
 	"os"
+
+	"github.com/ncarlier/webhookd/pkg/logger"
 )
 
 // CompressFile is a simple file gzipper.
@@ -17,7 +18,7 @@ func CompressFile(filename string) (zipfile string, err error) {
 	}
 	out, err := os.Create(zipfile)
 	if err != nil {
-		log.Println("Unable to create gzip file", err)
+		logger.Error.Println("Unable to create gzip file", err)
 		return
 	}
 
@@ -30,9 +31,9 @@ func CompressFile(filename string) (zipfile string, err error) {
 
 	_, err = bufin.WriteTo(gw)
 	if err != nil {
-		log.Println("Unable to write into the gzip file", err)
+		logger.Error.Println("Unable to write into the gzip file", err)
 		return
 	}
-	log.Println("Gzip file created: ", zipfile)
+	logger.Debug.Println("Gzip file created: ", zipfile)
 	return
 }

pkg/worker/dispatcher.go

@@ -1,6 +1,8 @@
 package worker
 
-import "log"
+import (
+	"github.com/ncarlier/webhookd/pkg/logger"
+)
 
 var WorkerQueue chan chan WorkRequest
 var WorkQueue = make(chan WorkRequest, 100)
@@ -12,7 +14,7 @@ func StartDispatcher(nworkers int) {
 
 	// Now, create all of our workers.
 	for i := 0; i < nworkers; i++ {
-		log.Println("Starting worker", i+1)
+		logger.Debug.Println("Starting worker", i+1)
 		worker := NewWorker(i+1, WorkerQueue)
 		worker.Start()
 	}
@@ -21,11 +23,11 @@ func StartDispatcher(nworkers int) {
 		for {
 			select {
 			case work := <-WorkQueue:
-				log.Println("Received work request:", work.Name)
+				logger.Debug.Println("Received work request:", work.Name)
 				go func() {
 					worker := <-WorkerQueue
 
-					log.Println("Dispatching work request:", work.Name)
+					logger.Debug.Println("Dispatching work request:", work.Name)
 					worker <- work
 				}()
 			}

pkg/worker/worker.go

@@ -2,8 +2,8 @@ package worker
 
 import (
 	"fmt"
-	"log"
 
+	"github.com/ncarlier/webhookd/pkg/logger"
 	"github.com/ncarlier/webhookd/pkg/notification"
 	"github.com/ncarlier/webhookd/pkg/tools"
 )
@@ -41,7 +41,7 @@ func (w Worker) Start() {
 			select {
 			case work := <-w.Work:
 				// Receive a work request.
-				log.Printf("Worker%d received work request: %s\n", w.ID, work.Name)
+				logger.Debug.Printf("Worker%d received work request: %s\n", w.ID, work.Name)
 				filename, err := runScript(&work)
 				if err != nil {
 					subject := fmt.Sprintf("Webhook %s FAILED.", work.Name)
@@ -54,7 +54,7 @@ func (w Worker) Start() {
 				}
 				close(work.MessageChan)
 			case <-w.QuitChan:
-				log.Printf("Stopping worker%d...\n", w.ID)
+				logger.Debug.Printf("Stopping worker%d...\n", w.ID)
 				return
 			}
 		}
@@ -72,11 +72,11 @@ func (w Worker) Stop() {
 func notify(subject string, text string, outfilename string) {
 	var notifier, err = notification.NotifierFactory()
 	if err != nil {
-		log.Println("Unable to get the notifier. Notification skipped:", err)
+		logger.Info.Println("Unable to get the notifier. Notification skipped:", err)
 		return
 	}
 	if notifier == nil {
-		log.Println("Notification provider not found. Notification skipped.")
+		logger.Error.Println("Notification provider not found. Notification skipped.")
 		return
 	}