feat(): structured logging

This commit is contained in:
Nicolas Carlier 2023-10-03 18:02:57 +00:00
parent 65427c5c72
commit 0d802d03eb
25 changed files with 164 additions and 223 deletions

View File

@ -5,9 +5,6 @@
# Hook execution logs location, default is OS temporary directory # Hook execution logs location, default is OS temporary directory
#WHD_HOOK_LOG_DIR="/tmp" #WHD_HOOK_LOG_DIR="/tmp"
# Output hook execution logs to server logs, default is false
#WHD_HOOK_LOG_OUTPUT=false
# Maximum hook execution time in second, default is 10 # Maximum hook execution time in second, default is 10
#WHD_HOOK_TIMEOUT=10 #WHD_HOOK_TIMEOUT=10
@ -15,9 +12,18 @@
# Example: `localhost:8080` or `:8080` for all interfaces # Example: `localhost:8080` or `:8080` for all interfaces
#WHD_LISTEN_ADDR=":8080" #WHD_LISTEN_ADDR=":8080"
# Log level (debug, info, warn, error), default is "info" # Log level (debug, info, warn or error), default is "info"
#WHD_LOG_LEVEL=info #WHD_LOG_LEVEL=info
# Log format (text or json), default is "text"
#WHD_LOG_FORMAT=text
# Log HTTP request, default is false
#WHD_LOG_HTTP_REQUEST=false
# Log hook execution output, default is false
#WHD_LOG_HOOK_OUTPUT=false
# Number of workers to start, default is 2 # Number of workers to start, default is 2
#WHD_NB_WORKERS=2 #WHD_NB_WORKERS=2

31
main.go
View File

@ -3,6 +3,8 @@ package main
import ( import (
"context" "context"
"flag" "flag"
"log"
"log/slog"
"net/http" "net/http"
"os" "os"
"os/signal" "os/signal"
@ -31,31 +33,29 @@ func main() {
os.Exit(0) os.Exit(0)
} }
if conf.HookLogOutput {
logger.Init(conf.LogLevel, "out")
} else {
logger.Init(conf.LogLevel)
}
if conf.HookLogDir == "" { if conf.HookLogDir == "" {
conf.HookLogDir = os.TempDir() conf.HookLogDir = os.TempDir()
} }
if err := conf.Validate(); err != nil { if err := conf.Validate(); err != nil {
logger.Error.Fatal("invalid configuration:", err) log.Fatal("invalid configuration:", err)
} }
logger.Debug.Println("starting webhookd server...") logger.Configure(conf.LogFormat, conf.LogLevel)
logger.HookOutputEnabled = conf.LogHookOutput
logger.RequestOutputEnabled = conf.LogHTTPRequest
slog.Debug("starting webhookd server...")
srv := server.NewServer(conf) srv := server.NewServer(conf)
// Configure notification // Configure notification
if err := notification.Init(conf.NotificationURI); err != nil { if err := notification.Init(conf.NotificationURI); err != nil {
logger.Error.Fatalf("unable to create notification channel: %v\n", err) slog.Error("unable to create notification channel", "err", err)
} }
// Start the dispatcher. // Start the dispatcher.
logger.Debug.Printf("starting the dispatcher with %d workers...\n", conf.NbWorkers) slog.Debug("starting the dispatcher...", "workers", conf.NbWorkers)
worker.StartDispatcher(conf.NbWorkers) worker.StartDispatcher(conf.NbWorkers)
done := make(chan bool) done := make(chan bool)
@ -64,24 +64,25 @@ func main() {
go func() { go func() {
<-quit <-quit
logger.Debug.Println("server is shutting down...") slog.Debug("server is shutting down...")
api.Shutdown() api.Shutdown()
ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
defer cancel() defer cancel()
if err := srv.Shutdown(ctx); err != nil { if err := srv.Shutdown(ctx); err != nil {
logger.Error.Fatalf("could not gracefully shutdown the server: %v\n", err) slog.Error("could not gracefully shutdown the server", "err", err)
} }
close(done) close(done)
}() }()
logger.Info.Println("server is ready to handle requests at", conf.ListenAddr)
api.Start() api.Start()
slog.Info("server started", "addr", conf.ListenAddr)
if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed { if err := srv.ListenAndServe(); err != nil && err != http.ErrServerClosed {
logger.Error.Fatalf("could not listen on %s : %v\n", conf.ListenAddr, err) slog.Error("unable to start the server", "addr", conf.ListenAddr, "err", err)
os.Exit(1)
} }
<-done <-done
logger.Debug.Println("server stopped") slog.Debug("server stopped")
} }

View File

@ -3,7 +3,7 @@ package api
import ( import (
"fmt" "fmt"
"io" "io"
"io/ioutil" "log/slog"
"mime" "mime"
"net/http" "net/http"
"path" "path"
@ -13,7 +13,6 @@ import (
"github.com/ncarlier/webhookd/pkg/config" "github.com/ncarlier/webhookd/pkg/config"
"github.com/ncarlier/webhookd/pkg/hook" "github.com/ncarlier/webhookd/pkg/hook"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/worker" "github.com/ncarlier/webhookd/pkg/worker"
) )
@ -64,13 +63,13 @@ func triggerWebhook(w http.ResponseWriter, r *http.Request) {
} }
_, err := hook.ResolveScript(scriptDir, hookName) _, err := hook.ResolveScript(scriptDir, hookName)
if err != nil { if err != nil {
logger.Error.Println(err.Error()) slog.Error("hooke not found", "err", err.Error())
http.Error(w, "hook not found", http.StatusNotFound) http.Error(w, "hook not found", http.StatusNotFound)
return return
} }
if err = r.ParseForm(); err != nil { if err = r.ParseForm(); err != nil {
logger.Error.Printf("error reading from-data: %v", err) slog.Error("error reading from-data", "err", err)
http.Error(w, "unable to parse request form", http.StatusBadRequest) http.Error(w, "unable to parse request form", http.StatusBadRequest)
return return
} }
@ -81,9 +80,9 @@ func triggerWebhook(w http.ResponseWriter, r *http.Request) {
if ct != "" { if ct != "" {
mediatype, _, _ := mime.ParseMediaType(ct) mediatype, _, _ := mime.ParseMediaType(ct)
if strings.HasPrefix(mediatype, "text/") || mediatype == "application/json" { if strings.HasPrefix(mediatype, "text/") || mediatype == "application/json" {
body, err = ioutil.ReadAll(r.Body) body, err = io.ReadAll(r.Body)
if err != nil { if err != nil {
logger.Error.Printf("error reading body: %v", err) slog.Error("error reading body", "err", err)
http.Error(w, "unable to read request body", http.StatusBadRequest) http.Error(w, "unable to read request body", http.StatusBadRequest)
return return
} }
@ -107,7 +106,7 @@ func triggerWebhook(w http.ResponseWriter, r *http.Request) {
OutputDir: outputDir, OutputDir: outputDir,
}) })
if err != nil { if err != nil {
logger.Error.Printf("error creating hook job: %v", err) slog.Error("error creating hook job", "err", err)
http.Error(w, "unable to create hook job", http.StatusInternalServerError) http.Error(w, "unable to create hook job", http.StatusInternalServerError)
return return
} }
@ -151,7 +150,7 @@ func getWebhookLog(w http.ResponseWriter, r *http.Request) {
hookName := path.Dir(strings.TrimPrefix(r.URL.Path, "/")) hookName := path.Dir(strings.TrimPrefix(r.URL.Path, "/"))
_, err := hook.ResolveScript(scriptDir, hookName) _, err := hook.ResolveScript(scriptDir, hookName)
if err != nil { if err != nil {
logger.Error.Println(err.Error()) slog.Error(err.Error())
http.Error(w, err.Error(), http.StatusNotFound) http.Error(w, err.Error(), http.StatusNotFound)
return return
} }
@ -159,7 +158,7 @@ func getWebhookLog(w http.ResponseWriter, r *http.Request) {
// Retrieve log file // Retrieve log file
logFile, err := hook.Logs(id, hookName, outputDir) logFile, err := hook.Logs(id, hookName, outputDir)
if err != nil { if err != nil {
logger.Error.Println(err.Error()) slog.Error(err.Error())
http.Error(w, err.Error(), http.StatusInternalServerError) http.Error(w, err.Error(), http.StatusInternalServerError)
return return
} }

View File

@ -1,9 +1,10 @@
package api package api
import ( import (
"log/slog"
"github.com/ncarlier/webhookd/pkg/auth" "github.com/ncarlier/webhookd/pkg/auth"
"github.com/ncarlier/webhookd/pkg/config" "github.com/ncarlier/webhookd/pkg/config"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/middleware" "github.com/ncarlier/webhookd/pkg/middleware"
"github.com/ncarlier/webhookd/pkg/truststore" "github.com/ncarlier/webhookd/pkg/truststore"
) )
@ -24,7 +25,7 @@ func buildMiddlewares(conf *config.Config) middleware.Middlewares {
// Load trust store... // Load trust store...
ts, err := truststore.New(conf.TrustStoreFile) ts, err := truststore.New(conf.TrustStoreFile)
if err != nil { if err != nil {
logger.Warning.Printf("unable to load trust store (\"%s\"): %s\n", conf.TrustStoreFile, err) slog.Warn("unable to load trust store", "filename", conf.TrustStoreFile, "err", err)
} }
if ts != nil { if ts != nil {
middlewares = middlewares.UseAfter(middleware.Signature(ts)) middlewares = middlewares.UseAfter(middleware.Signature(ts))
@ -33,7 +34,7 @@ func buildMiddlewares(conf *config.Config) middleware.Middlewares {
// Load authenticator... // Load authenticator...
authenticator, err := auth.NewHtpasswdFromFile(conf.PasswdFile) authenticator, err := auth.NewHtpasswdFromFile(conf.PasswdFile)
if err != nil { if err != nil {
logger.Debug.Printf("unable to load htpasswd file (\"%s\"): %s\n", conf.PasswdFile, err) slog.Debug("unable to load htpasswd file", "filename", conf.PasswdFile, "err", err)
} }
if authenticator != nil { if authenticator != nil {
middlewares = middlewares.UseAfter(middleware.AuthN(authenticator)) middlewares = middlewares.UseAfter(middleware.AuthN(authenticator))

View File

@ -15,10 +15,12 @@ type Config struct {
NbWorkers int `flag:"nb-workers" desc:"Number of workers to start" default:"2"` NbWorkers int `flag:"nb-workers" desc:"Number of workers to start" default:"2"`
HookTimeout int `flag:"hook-timeout" desc:"Maximum hook execution time in second" default:"10"` HookTimeout int `flag:"hook-timeout" desc:"Maximum hook execution time in second" default:"10"`
HookLogDir string `flag:"hook-log-dir" desc:"Hook execution logs location" default:""` HookLogDir string `flag:"hook-log-dir" desc:"Hook execution logs location" default:""`
HookLogOutput bool `flag:"hook-log-output" desc:"Output hook execution logs to server logs" default:"false"`
ScriptDir string `flag:"scripts" desc:"Scripts location" default:"scripts"` ScriptDir string `flag:"scripts" desc:"Scripts location" default:"scripts"`
PasswdFile string `flag:"passwd-file" desc:"Password file for basic HTTP authentication" default:".htpasswd"` PasswdFile string `flag:"passwd-file" desc:"Password file for basic HTTP authentication" default:".htpasswd"`
LogLevel string `flag:"log-level" desc:"Log level (debug, info, warn, error)" default:"info"` LogLevel string `flag:"log-level" desc:"Log level (debug, info, warn, error)" default:"info"`
LogFormat string `flag:"log-format" desc:"Log format (json, text)" default:"text"`
LogHookOutput bool `flag:"log-hook-output" desc:"Log hook execution output" default:"false"`
LogHTTPRequest bool `flag:"log-http-request" desc:"Log HTTP request" default:"false"`
StaticDir string `flag:"static-dir" desc:"Static file directory to serve on /static path" default:""` StaticDir string `flag:"static-dir" desc:"Static file directory to serve on /static path" default:""`
StaticPath string `flag:"static-path" desc:"Path to serve static file directory" default:"/static"` StaticPath string `flag:"static-path" desc:"Path to serve static file directory" default:"/static"`
NotificationURI string `flag:"notification-uri" desc:"Notification URI"` NotificationURI string `flag:"notification-uri" desc:"Notification URI"`

View File

@ -5,6 +5,7 @@ import (
"bytes" "bytes"
"fmt" "fmt"
"io" "io"
"log/slog"
"os" "os"
"os/exec" "os/exec"
"path" "path"
@ -31,6 +32,7 @@ type Job struct {
args []string args []string
MessageChan chan []byte MessageChan chan []byte
timeout int timeout int
start time.Time
status Status status Status
logFilename string logFilename string
err error err error
@ -83,14 +85,27 @@ func (job *Job) Meta() []string {
func (job *Job) Terminate(err error) error { func (job *Job) Terminate(err error) error {
job.mutex.Lock() job.mutex.Lock()
defer job.mutex.Unlock() defer job.mutex.Unlock()
job.status = Success
if err != nil { if err != nil {
job.status = Error job.status = Error
job.err = err job.err = err
logger.Info.Printf("hook %s#%d done [ERROR]\n", job.Name(), job.ID()) slog.Error(
"hook executed",
"hook", job.Name(),
"id", job.ID(),
"status", "error",
"err", err,
"took", time.Since(job.start).Microseconds(),
)
return err return err
} }
job.status = Success slog.Info(
logger.Info.Printf("hook %s#%d done [SUCCESS]\n", job.Name(), job.ID()) "hook executed",
"hook", job.Name(),
"id", job.ID(),
"status", "success",
"took", time.Since(job.start).Microseconds(),
)
return nil return nil
} }
@ -160,9 +175,8 @@ func (job *Job) Run() error {
return fmt.Errorf("unable to run job: status=%s", job.StatusLabel()) return fmt.Errorf("unable to run job: status=%s", job.StatusLabel())
} }
job.status = Running job.status = Running
logger.Info.Printf("hook %s#%d started...\n", job.name, job.id) job.start = time.Now()
logger.Debug.Printf("hook %s#%d script: %s\n", job.name, job.id, job.script) slog.Info("executing hook...", "hook", job.name, "id", job.id)
logger.Debug.Printf("hook %s#%d parameter: %v\n", job.name, job.id, job.args)
binary, err := exec.LookPath(job.script) binary, err := exec.LookPath(job.script)
if err != nil { if err != nil {
@ -184,7 +198,7 @@ func (job *Job) Run() error {
return job.Terminate(err) return job.Terminate(err)
} }
defer logFile.Close() defer logFile.Close()
logger.Debug.Printf("hook %s#%d output file: %s\n", job.name, job.id, logFile.Name()) slog.Debug("hook details", "hook", job.name, "id", job.id, "script", job.script, "args", job.args, "output", logFile.Name())
wLogFile := bufio.NewWriter(logFile) wLogFile := bufio.NewWriter(logFile)
defer wLogFile.Flush() defer wLogFile.Flush()
@ -219,26 +233,32 @@ func (job *Job) Run() error {
if !job.IsTerminated() { if !job.IsTerminated() {
job.MessageChan <- []byte(line) job.MessageChan <- []byte(line)
} else { } else {
logger.Error.Printf("hook %s#%d is over ; unable to write more data into the channel: %s\n", job.name, job.id, line) slog.Error("hook execution done ; unable to write more data into the channel", "hook", job.name, "id", job.id, "line", line)
break break
} }
// write to stdout if configured // write to stdout if configured
logger.Output.Println(line) logger.LogIf(
logger.HookOutputEnabled,
slog.LevelInfo+1,
line,
"hook", job.name,
"id", job.id,
)
// writing to outfile // writing to outfile
if _, err := wLogFile.WriteString(line + "\n"); err != nil { if _, err := wLogFile.WriteString(line + "\n"); err != nil {
logger.Error.Println("error while writing into the log file:", logFile.Name(), err) slog.Error("error while writing into the log file", "filename", logFile.Name(), "err", err)
break break
} }
} }
if err := scanner.Err(); err != nil { if err := scanner.Err(); err != nil {
logger.Error.Printf("hook %s#%d is unable to read script stdout: %v\n", job.name, job.id, err) slog.Error("hook is unable to read script stdout", "hook", job.name, "id", job.id, "err", err)
} }
wg.Done() wg.Done()
}(cmdReader) }(cmdReader)
// Start timeout timer // Start timeout timer
timer := time.AfterFunc(time.Duration(job.timeout)*time.Second, func() { timer := time.AfterFunc(time.Duration(job.timeout)*time.Second, func() {
logger.Warning.Printf("hook %s#%d has timed out (%ds): killing process #%d ...\n", job.name, job.id, job.timeout, cmd.Process.Pid) slog.Warn("hook has timed out: killing process...", "hook", job.name, "id", job.id, "timeout", job.timeout, "pid", cmd.Process.Pid)
syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL) syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL)
}) })

View File

@ -1,13 +1,13 @@
package test package test
import ( import (
"log/slog"
"os" "os"
"strconv" "strconv"
"testing" "testing"
"github.com/ncarlier/webhookd/pkg/assert" "github.com/ncarlier/webhookd/pkg/assert"
"github.com/ncarlier/webhookd/pkg/hook" "github.com/ncarlier/webhookd/pkg/hook"
"github.com/ncarlier/webhookd/pkg/logger"
) )
func printJobMessages(job *hook.Job) { func printJobMessages(job *hook.Job) {
@ -17,13 +17,12 @@ func printJobMessages(job *hook.Job) {
if !open { if !open {
break break
} }
logger.Info.Println(string(msg)) slog.Info(string(msg))
} }
}() }()
} }
func TestHookJob(t *testing.T) { func TestHookJob(t *testing.T) {
logger.Init("debug", "out")
req := &hook.Request{ req := &hook.Request{
Name: "test_simple", Name: "test_simple",
Method: "GET", Method: "GET",
@ -54,7 +53,6 @@ func TestHookJob(t *testing.T) {
} }
func TestWorkRunnerWithError(t *testing.T) { func TestWorkRunnerWithError(t *testing.T) {
logger.Init("debug")
req := &hook.Request{ req := &hook.Request{
Name: "test_error", Name: "test_error",
Method: "POST", Method: "POST",
@ -75,7 +73,6 @@ func TestWorkRunnerWithError(t *testing.T) {
} }
func TestWorkRunnerWithTimeout(t *testing.T) { func TestWorkRunnerWithTimeout(t *testing.T) {
logger.Init("debug")
req := &hook.Request{ req := &hook.Request{
Name: "test_timeout", Name: "test_timeout",
Method: "POST", Method: "POST",

View File

@ -1,50 +0,0 @@
package logger
import (
"os"
"github.com/mattn/go-isatty"
)
var (
nocolor = "\033[0m"
red = "\033[0;31m"
green = "\033[0;32m"
orange = "\033[0;33m"
blue = "\033[0;34m"
purple = "\033[0;35m"
cyan = "\033[0;36m"
gray = "\033[0;37m"
)
func colorize(text string, color string) string {
if isatty.IsTerminal(os.Stdout.Fd()) {
return color + text + nocolor
}
return text
}
// Gray ANSI color applied to a string
func Gray(text string) string {
return colorize(text, gray)
}
// Green ANSI color applied to a string
func Green(text string) string {
return colorize(text, green)
}
// Orange ANSI color applied to a string
func Orange(text string) string {
return colorize(text, orange)
}
// Red ANSI color applied to a string
func Red(text string) string {
return colorize(text, red)
}
// Purple ANSI color applied to a string
func Purple(text string) string {
return colorize(text, purple)
}

46
pkg/logger/logger.go Normal file
View File

@ -0,0 +1,46 @@
package logger
import (
"context"
"log/slog"
"os"
)
var (
HookOutputEnabled = false
RequestOutputEnabled = false
)
// Configure logger
func Configure(format, level string) {
logLevel := slog.LevelDebug
switch level {
case "info":
logLevel = slog.LevelInfo
case "warn":
logLevel = slog.LevelWarn
case "error":
logLevel = slog.LevelError
}
opts := slog.HandlerOptions{
Level: logLevel,
AddSource: logLevel == slog.LevelDebug,
}
var logger *slog.Logger
if format == "json" {
logger = slog.New(slog.NewJSONHandler(os.Stdout, &opts))
} else {
logger = slog.New(slog.NewTextHandler(os.Stdout, &opts))
}
slog.SetDefault(logger)
}
// LogIf writ log on condition
func LogIf(condition bool, level slog.Level, msg string, args ...any) {
if condition {
slog.Log(context.Background(), level, msg, args...)
}
}

View File

@ -1,66 +0,0 @@
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
// Output special level used for script output
Output *log.Logger
)
// Init logger level
func Init(level string, with ...string) {
var debugHandle, infoHandle, warnHandle, errorHandle, outputHandle io.Writer
debugHandle = os.Stdout
infoHandle = os.Stdout
warnHandle = os.Stderr
errorHandle = os.Stderr
outputHandle = ioutil.Discard
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
}
if contains(with, "out") {
outputHandle = os.Stdout
}
commonFlags := log.LstdFlags | log.Lmicroseconds
if level == "debug" {
commonFlags = log.LstdFlags | log.Lmicroseconds | log.Lshortfile
}
Debug = log.New(debugHandle, Gray("DBG "), commonFlags)
Info = log.New(infoHandle, Green("INF "), commonFlags)
Warning = log.New(warnHandle, Orange("WRN "), commonFlags)
Error = log.New(errorHandle, Red("ERR "), commonFlags)
Output = log.New(outputHandle, Purple("OUT "), commonFlags)
}
func contains(s []string, e string) bool {
for _, a := range s {
if a == e {
return true
}
}
return false
}

View File

@ -2,6 +2,7 @@ package middleware
import ( import (
"fmt" "fmt"
"log/slog"
"net/http" "net/http"
"strings" "strings"
"time" "time"
@ -25,16 +26,18 @@ func Logger(next http.Handler) http.Handler {
if !ok { if !ok {
requestID = "0" requestID = "0"
} }
logger.Info.Printf( logger.LogIf(
"%s - - [%s] %q %d %d %q %q %q", logger.RequestOutputEnabled,
getRequestIP(r), slog.LevelInfo+1,
start.Format("02/Jan/2006:15:04:05 -0700"),
fmt.Sprintf("%s %s %s", r.Method, r.URL, r.Proto), fmt.Sprintf("%s %s %s", r.Method, r.URL, r.Proto),
o.status, "ip", getRequestIP(r),
o.written, "time", start.Format("02/Jan/2006:15:04:05 -0700"),
r.Referer(), "duration", time.Since(start).Milliseconds(),
r.UserAgent(), "status", o.status,
fmt.Sprintf("REQID=%s", requestID), "bytes", o.written,
"referer", r.Referer(),
"ua", r.UserAgent(),
"reqid", requestID,
) )
}() }()
next.ServeHTTP(o, r) next.ServeHTTP(o, r)

View File

@ -12,14 +12,11 @@ import (
"time" "time"
"github.com/ncarlier/webhookd/pkg/assert" "github.com/ncarlier/webhookd/pkg/assert"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/middleware/signature" "github.com/ncarlier/webhookd/pkg/middleware/signature"
"github.com/ncarlier/webhookd/pkg/truststore" "github.com/ncarlier/webhookd/pkg/truststore"
) )
func TestEd5519Signature(t *testing.T) { func TestEd5519Signature(t *testing.T) {
logger.Init("warn")
pubkey, privkey, err := ed25519.GenerateKey(rand.Reader) pubkey, privkey, err := ed25519.GenerateKey(rand.Reader)
assert.Nil(t, err, "") assert.Nil(t, err, "")

View File

@ -10,7 +10,6 @@ import (
"github.com/go-fed/httpsig" "github.com/go-fed/httpsig"
"github.com/ncarlier/webhookd/pkg/assert" "github.com/ncarlier/webhookd/pkg/assert"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/middleware/signature" "github.com/ncarlier/webhookd/pkg/middleware/signature"
"github.com/ncarlier/webhookd/pkg/truststore" "github.com/ncarlier/webhookd/pkg/truststore"
) )
@ -25,8 +24,6 @@ func assertSigner(t *testing.T) httpsig.Signer {
} }
func TestHTTPSignature(t *testing.T) { func TestHTTPSignature(t *testing.T) {
logger.Init("warn")
privkey, err := rsa.GenerateKey(rand.Reader, 2048) privkey, err := rsa.GenerateKey(rand.Reader, 2048)
assert.Nil(t, err, "") assert.Nil(t, err, "")
pubkey := &privkey.PublicKey pubkey := &privkey.PublicKey

View File

@ -3,13 +3,13 @@ package http
import ( import (
"bytes" "bytes"
"encoding/json" "encoding/json"
"log/slog"
"net/http" "net/http"
"net/url" "net/url"
"strconv" "strconv"
"strings" "strings"
"github.com/ncarlier/webhookd/pkg/helper" "github.com/ncarlier/webhookd/pkg/helper"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/notification" "github.com/ncarlier/webhookd/pkg/notification"
) )
@ -27,7 +27,7 @@ type httpNotifier struct {
} }
func newHTTPNotifier(uri *url.URL) (notification.Notifier, error) { func newHTTPNotifier(uri *url.URL) (notification.Notifier, error) {
logger.Info.Println("using HTTP notification system: ", uri.String()) slog.Info("using HTTP notification system ", "üri", uri.Opaque)
return &httpNotifier{ return &httpNotifier{
URL: uri, URL: uri,
PrefixFilter: helper.GetValueOrAlt(uri.Query(), "prefix", "notify:"), PrefixFilter: helper.GetValueOrAlt(uri.Query(), "prefix", "notify:"),
@ -65,7 +65,7 @@ func (n *httpNotifier) Notify(result notification.HookResult) error {
return err return err
} }
resp.Body.Close() resp.Body.Close()
logger.Info.Printf("job %s#%d notification sent to %s\n", result.Name(), result.ID(), n.URL.String()) slog.Info("notification sent", "hook", result.Name(), "id", result.ID(), "to", n.URL.Opaque)
return nil return nil
} }

View File

@ -1,7 +1,7 @@
package notification package notification
import ( import (
"github.com/ncarlier/webhookd/pkg/logger" "log/slog"
) )
// Notifier is able to send a notification. // Notifier is able to send a notification.
@ -17,7 +17,7 @@ func Notify(result HookResult) {
return return
} }
if err := notifier.Notify(result); err != nil { if err := notifier.Notify(result); err != nil {
logger.Error.Printf("unable to send notification for webhook %s#%d: %v\n", result.Name(), result.ID(), err) slog.Error("unable to send notification", "webhook", result.Name(), "id", result.ID(), "err", err)
} }
} }

View File

@ -3,6 +3,7 @@ package smtp
import ( import (
"crypto/tls" "crypto/tls"
"fmt" "fmt"
"log/slog"
"net" "net"
"net/smtp" "net/smtp"
"net/url" "net/url"
@ -11,7 +12,6 @@ import (
"time" "time"
"github.com/ncarlier/webhookd/pkg/helper" "github.com/ncarlier/webhookd/pkg/helper"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/notification" "github.com/ncarlier/webhookd/pkg/notification"
) )
@ -28,7 +28,7 @@ type smtpNotifier struct {
} }
func newSMTPNotifier(uri *url.URL) (notification.Notifier, error) { func newSMTPNotifier(uri *url.URL) (notification.Notifier, error) {
logger.Info.Println("using SMTP notification system:", uri.Opaque) slog.Info("using SMTP notification system", "uri", uri.Opaque)
q := uri.Query() q := uri.Query()
return &smtpNotifier{ return &smtpNotifier{
Host: helper.GetValueOrAlt(q, "smtp", "localhost:25"), Host: helper.GetValueOrAlt(q, "smtp", "localhost:25"),
@ -128,7 +128,7 @@ func (n *smtpNotifier) Notify(result notification.HookResult) error {
return err return err
} }
logger.Info.Printf("job %s#%d notification sent to %s\n", result.Name(), result.ID(), n.To) slog.Info("notification sent", "hook", result.Name(), "id", result.ID(), "to", n.To)
// Send the QUIT command and close the connection. // Send the QUIT command and close the connection.
return client.Quit() return client.Quit()

View File

@ -2,6 +2,7 @@ package server
import ( import (
"context" "context"
"log/slog"
"net/http" "net/http"
"os" "os"
"os/user" "os/user"
@ -9,7 +10,6 @@ import (
"github.com/ncarlier/webhookd/pkg/api" "github.com/ncarlier/webhookd/pkg/api"
"github.com/ncarlier/webhookd/pkg/config" "github.com/ncarlier/webhookd/pkg/config"
"github.com/ncarlier/webhookd/pkg/logger"
"golang.org/x/crypto/acme/autocert" "golang.org/x/crypto/acme/autocert"
) )
@ -48,12 +48,13 @@ func (s *Server) Shutdown(ctx context.Context) error {
// NewServer create new HTTP(s) server // NewServer create new HTTP(s) server
func NewServer(cfg *config.Config) *Server { func NewServer(cfg *config.Config) *Server {
logger := slog.NewLogLogger(slog.Default().Handler(), slog.LevelError)
server := &Server{ server := &Server{
tls: cfg.TLS, tls: cfg.TLS,
self: &http.Server{ self: &http.Server{
Addr: cfg.ListenAddr, Addr: cfg.ListenAddr,
Handler: api.NewRouter(cfg), Handler: api.NewRouter(cfg),
ErrorLog: logger.Error, ErrorLog: logger,
}, },
} }
if server.tls { if server.tls {

View File

@ -2,14 +2,14 @@ package truststore
import ( import (
"crypto" "crypto"
"io/ioutil" "log/slog"
"os"
"github.com/ncarlier/webhookd/pkg/logger"
"golang.org/x/crypto/pkcs12" "golang.org/x/crypto/pkcs12"
) )
func newP12TrustStore(filename string) (TrustStore, error) { func newP12TrustStore(filename string) (TrustStore, error) {
data, err := ioutil.ReadFile(filename) data, err := os.ReadFile(filename)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@ -25,7 +25,7 @@ func newP12TrustStore(filename string) (TrustStore, error) {
keyID := string(cert.Subject.CommonName) keyID := string(cert.Subject.CommonName)
result.Keys[keyID] = cert.PublicKey result.Keys[keyID] = cert.PublicKey
logger.Debug.Printf("certificate \"%s\" loaded into the trustore", keyID) slog.Debug("certificate loaded into the trustore", "id", keyID)
return result, nil return result, nil
} }

View File

@ -5,13 +5,12 @@ import (
"crypto/x509" "crypto/x509"
"encoding/pem" "encoding/pem"
"fmt" "fmt"
"io/ioutil" "log/slog"
"os"
"github.com/ncarlier/webhookd/pkg/logger"
) )
func newPEMTrustStore(filename string) (TrustStore, error) { func newPEMTrustStore(filename string) (TrustStore, error) {
raw, err := ioutil.ReadFile(filename) raw, err := os.ReadFile(filename)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@ -37,7 +36,7 @@ func newPEMTrustStore(filename string) (TrustStore, error) {
} }
result.Keys[keyID] = key result.Keys[keyID] = key
logger.Debug.Printf("public key \"%s\" loaded into the trustore", keyID) slog.Debug("public key loaded into the trustore", "id", keyID)
case "CERTIFICATE": case "CERTIFICATE":
cert, err := x509.ParseCertificate(block.Bytes) cert, err := x509.ParseCertificate(block.Bytes)
if err != nil { if err != nil {
@ -45,7 +44,7 @@ func newPEMTrustStore(filename string) (TrustStore, error) {
} }
keyID := string(cert.Subject.CommonName) keyID := string(cert.Subject.CommonName)
result.Keys[keyID] = cert.PublicKey result.Keys[keyID] = cert.PublicKey
logger.Debug.Printf("certificate \"%s\" loaded into the trustore", keyID) slog.Debug("certificate loaded into the trustore", "id", keyID)
} }
raw = rest raw = rest
} }

View File

@ -5,13 +5,11 @@ import (
"testing" "testing"
"github.com/ncarlier/webhookd/pkg/assert" "github.com/ncarlier/webhookd/pkg/assert"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/truststore" "github.com/ncarlier/webhookd/pkg/truststore"
) )
func TestTrustStoreWithP12(t *testing.T) { func TestTrustStoreWithP12(t *testing.T) {
t.Skip() t.Skip()
logger.Init("warn")
ts, err := truststore.New("test.p12") ts, err := truststore.New("test.p12")
assert.Nil(t, err, "") assert.Nil(t, err, "")

View File

@ -5,13 +5,10 @@ import (
"testing" "testing"
"github.com/ncarlier/webhookd/pkg/assert" "github.com/ncarlier/webhookd/pkg/assert"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/truststore" "github.com/ncarlier/webhookd/pkg/truststore"
) )
func TestTrustStoreWithNoKeyID(t *testing.T) { func TestTrustStoreWithNoKeyID(t *testing.T) {
logger.Init("warn")
ts, err := truststore.New("test-key-01.pem") ts, err := truststore.New("test-key-01.pem")
assert.Nil(t, err, "") assert.Nil(t, err, "")
assert.NotNil(t, ts, "") assert.NotNil(t, ts, "")
@ -24,8 +21,6 @@ func TestTrustStoreWithNoKeyID(t *testing.T) {
} }
func TestTrustStoreWithKeyID(t *testing.T) { func TestTrustStoreWithKeyID(t *testing.T) {
logger.Init("warn")
ts, err := truststore.New("test-key-02.pem") ts, err := truststore.New("test-key-02.pem")
assert.Nil(t, err, "") assert.Nil(t, err, "")
assert.NotNil(t, ts, "") assert.NotNil(t, ts, "")
@ -36,8 +31,6 @@ func TestTrustStoreWithKeyID(t *testing.T) {
} }
func TestTrustStoreWithCertificate(t *testing.T) { func TestTrustStoreWithCertificate(t *testing.T) {
logger.Init("warn")
ts, err := truststore.New("test-cert.pem") ts, err := truststore.New("test-cert.pem")
assert.Nil(t, err, "") assert.Nil(t, err, "")
assert.NotNil(t, ts, "") assert.NotNil(t, ts, "")
@ -48,8 +41,6 @@ func TestTrustStoreWithCertificate(t *testing.T) {
} }
func TestTrustStoreWithMultipleEntries(t *testing.T) { func TestTrustStoreWithMultipleEntries(t *testing.T) {
logger.Init("warn")
ts, err := truststore.New("test-multi.pem") ts, err := truststore.New("test-multi.pem")
assert.Nil(t, err, "") assert.Nil(t, err, "")
assert.NotNil(t, ts, "") assert.NotNil(t, ts, "")

View File

@ -3,9 +3,8 @@ package truststore
import ( import (
"crypto" "crypto"
"fmt" "fmt"
"log/slog"
"path/filepath" "path/filepath"
"github.com/ncarlier/webhookd/pkg/logger"
) )
// TrustStore is a generic interface to retrieve a public key // TrustStore is a generic interface to retrieve a public key
@ -31,7 +30,7 @@ func New(filename string) (store TrustStore, err error) {
return nil, nil return nil, nil
} }
logger.Debug.Printf("loading trust store: %s", filename) slog.Debug("loading trust store...", "filname", filename)
switch filepath.Ext(filename) { switch filepath.Ext(filename) {
case ".pem": case ".pem":
store, err = newPEMTrustStore(filename) store, err = newPEMTrustStore(filename)

View File

@ -1,7 +1,7 @@
package worker package worker
import ( import (
"github.com/ncarlier/webhookd/pkg/logger" "log/slog"
) )
// WorkerQueue is the global queue of Workers // WorkerQueue is the global queue of Workers
@ -17,7 +17,7 @@ func StartDispatcher(nworkers int) {
// Now, create all of our workers. // Now, create all of our workers.
for i := 0; i < nworkers; i++ { for i := 0; i < nworkers; i++ {
logger.Debug.Printf("starting worker #%d ...\n", i+1) slog.Debug("starting worker...", "worker", i+1)
worker := NewWorker(i+1, WorkerQueue) worker := NewWorker(i+1, WorkerQueue)
worker.Start() worker.Start()
} }
@ -29,7 +29,7 @@ func StartDispatcher(nworkers int) {
go func() { go func() {
worker := <-WorkerQueue worker := <-WorkerQueue
logger.Debug.Printf("dispatching hook request: %s#%d", work.Name(), work.ID()) slog.Debug("dispatching hook request", "hook", work.Name(), "id", work.ID())
worker <- work worker <- work
}() }()
} }

View File

@ -2,10 +2,10 @@ package worker
import ( import (
"fmt" "fmt"
"log/slog"
"github.com/ncarlier/webhookd/pkg/metric" "github.com/ncarlier/webhookd/pkg/metric"
"github.com/ncarlier/webhookd/pkg/logger"
"github.com/ncarlier/webhookd/pkg/notification" "github.com/ncarlier/webhookd/pkg/notification"
) )
@ -41,7 +41,7 @@ func (w Worker) Start() {
select { select {
case work := <-w.Work: case work := <-w.Work:
// Receive a work request. // Receive a work request.
logger.Debug.Printf("worker #%d received hook request: %s#%d\n", w.ID, work.Name(), work.ID()) slog.Debug("hook execution request received", "worker", w.ID, "hook", work.Name(), "id", work.ID())
metric.Requests.Add(1) metric.Requests.Add(1)
err := work.Run() err := work.Run()
if err != nil { if err != nil {
@ -53,7 +53,7 @@ func (w Worker) Start() {
work.Close() work.Close()
case <-w.QuitChan: case <-w.QuitChan:
logger.Debug.Printf("stopping worker #%d...\n", w.ID) slog.Debug("stopping worker...", "worker", w.ID)
return return
} }
} }

View File

@ -8,11 +8,11 @@ import (
"flag" "flag"
"fmt" "fmt"
"io" "io"
"io/ioutil"
"log" "log"
"net/http" "net/http"
"net/http/httputil" "net/http/httputil"
"net/url" "net/url"
"os"
"strings" "strings"
"time" "time"
@ -45,7 +45,7 @@ func main() {
log.Fatal("invalid target URL") log.Fatal("invalid target URL")
} }
keyBytes, err := ioutil.ReadFile(conf.KeyFile) keyBytes, err := os.ReadFile(conf.KeyFile)
if err != nil { if err != nil {
log.Fatal(err.Error()) log.Fatal(err.Error())
} }
@ -64,7 +64,7 @@ func main() {
var jsonBytes []byte var jsonBytes []byte
if conf.JSON != "" { if conf.JSON != "" {
var err error var err error
jsonBytes, err = ioutil.ReadFile(conf.JSON) jsonBytes, err = os.ReadFile(conf.JSON)
if err != nil { if err != nil {
log.Fatal(err.Error()) log.Fatal(err.Error())
} }