From f50091131b84c896016bbef3f62b00aaf93f3edd Mon Sep 17 00:00:00 2001 From: Nicolas Carlier Date: Tue, 9 Jan 2018 09:16:33 +0000 Subject: [PATCH] feat(): add custom logger --- main.go | 118 ++++++++++++++++++++++++++++-- pkg/hook/script.go | 5 +- pkg/logger/main.go | 44 +++++++++++ pkg/notification/http_notifier.go | 33 +++++---- pkg/notification/smtp_notifier.go | 4 +- pkg/tools/compress.go | 9 ++- pkg/worker/dispatcher.go | 10 ++- pkg/worker/worker.go | 10 +-- 8 files changed, 194 insertions(+), 39 deletions(-) create mode 100644 pkg/logger/main.go diff --git a/main.go b/main.go index 35642a7..c6eba7d 100644 --- a/main.go +++ b/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')") - nbWorkers = flag.Int("n", 2, "The number of workers to start") + healthy int32 +) + +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) - http.HandleFunc("/", api.WebhookHandler) - log.Fatal(http.ListenAndServe(*lAddr, nil)) + done := make(chan bool) + quit := make(chan os.Signal, 1) + 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)) + }) + } } diff --git a/pkg/hook/script.go b/pkg/hook/script.go index df5f570..7a58fcd 100644 --- a/pkg/hook/script.go +++ b/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) } diff --git a/pkg/logger/main.go b/pkg/logger/main.go new file mode 100644 index 0000000..72b1627 --- /dev/null +++ b/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) +} diff --git a/pkg/notification/http_notifier.go b/pkg/notification/http_notifier.go index 5449876..29a6dfe 100644 --- a/pkg/notification/http_notifier.go +++ b/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) - log.Println(res.Body) + logger.Error.Println("HTTP notification bad response: ", res.Status) + 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) - log.Println(res.Body) + logger.Error.Println("HTTP notification bad response: ", res.Status) + logger.Debug.Println(res.Body) return } - log.Println("HTTP notification sended.") + logger.Info.Println("HTTP notification sent.") } } diff --git a/pkg/notification/smtp_notifier.go b/pkg/notification/smtp_notifier.go index 996833f..2450b4a 100644 --- a/pkg/notification/smtp_notifier.go +++ b/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 { diff --git a/pkg/tools/compress.go b/pkg/tools/compress.go index 911be85..33b5d62 100644 --- a/pkg/tools/compress.go +++ b/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 } diff --git a/pkg/worker/dispatcher.go b/pkg/worker/dispatcher.go index 23de5dc..206abbf 100644 --- a/pkg/worker/dispatcher.go +++ b/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 }() } diff --git a/pkg/worker/worker.go b/pkg/worker/worker.go index b134485..d4264a3 100644 --- a/pkg/worker/worker.go +++ b/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 }