WIP: refactoring logging system

Makefile

@@ -3,6 +3,11 @@ VERSION=snapshot
 DOCKER_USER=
 DOCKER_PASSWORD=
 DOCKER_REPOSITORY=thecodingmachine
+DEFAULT_WAIT_TIMEOUT=10
+DEFAULT_LISTEN_PORT=3000
+DISABLE_GOOGLE_CHROME=0
+DISABLE_UNOCONV=0
+LOG_LEVEL=INFO
 
 # generate documentation.
 doc:
@@ -28,11 +33,11 @@ tests:
 # build Docker image.
 image:
 	docker build -t $(DOCKER_REPOSITORY)/gotenberg:base -f build/base/Dockerfile .
-	docker build --build-arg GOLANG_VERSION=$(GOLANG_VERSION) --build-arg VERSION=$(VERSION) -t $(DOCKER_REPO)/gotenberg:$(VERSION) -f build/package/Dockerfile .
+	docker build --build-arg GOLANG_VERSION=$(GOLANG_VERSION) --build-arg VERSION=$(VERSION) -t $(DOCKER_REPOSITORY)/gotenberg:$(VERSION) -f build/package/Dockerfile .
 
 # start the API using previously built Docker image.
 gotenberg:
-	docker run -it --rm -e DEBUG_PROCESS_STARTUP=1 -p "3000:3000" $(DOCKER_REPOSITORY)/gotenberg:$(VERSION)
+	docker run -it --rm -e DEFAULT_WAIT_TIMEOUT=$(DEFAULT_WAIT_TIMEOUT) -e DEFAULT_LISTEN_PORT=$(DEFAULT_LISTEN_PORT) -e DISABLE_GOOGLE_CHROME=$(DISABLE_GOOGLE_CHROME) -e DISABLE_UNOCONV=$(DISABLE_UNOCONV) -e LOG_LEVEL=$(LOG_LEVEL)  -p "3000:$(DEFAULT_LISTEN_PORT)" $(DOCKER_REPOSITORY)/gotenberg:$(VERSION)
 
 # publish Gotenberg images according to version.
 publish:

build/tests/docker-entrypoint.sh

@@ -10,7 +10,6 @@ go test github.com/thecodingmachine/gotenberg/internal/pkg/pm2 -run TestUnoconvS
 
 # Running others tests.
 go test -race -cover -covermode=atomic github.com/thecodingmachine/gotenberg/internal/app/api
-go test -race -cover -covermode=atomic github.com/thecodingmachine/gotenberg/internal/pkg/rand
 
 # Finally testing processes shutdown.
 go test github.com/thecodingmachine/gotenberg/internal/pkg/pm2 -run TestChromeShutdown

cmd/gotenberg/main.go

@@ -6,12 +6,11 @@ import (
 	"net/http"
 	"os"
 	"os/signal"
-	"strconv"
 	"time"
 
-	"github.com/labstack/echo/v4"
 	"github.com/thecodingmachine/gotenberg/internal/app/api"
-	"github.com/thecodingmachine/gotenberg/internal/pkg/notify"
+	conf "github.com/thecodingmachine/gotenberg/internal/pkg/config"
+	log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/pm2"
 )
 
@@ -19,116 +18,37 @@ import (
 // nolint: gochecknoglobals
 var version = "snapshot"
 
-const (
-	defaultWaitTimeoutEnvVar        = "DEFAULT_WAIT_TIMEOUT"
-	defaultListenPortEnvVar         = "DEFAULT_LISTEN_PORT"
-	disableGoogleChromeEnvVar       = "DISABLE_GOOGLE_CHROME"
-	disableUnoconvEnvVar            = "DISABLE_UNOCONV"
-	disableHealthcheckLoggingEnvVar = "DISABLE_HEALTHCHECK_LOGGING"
-	debugProcessStartup             = "DEBUG_PROCESS_STARTUP"
-)
-
-func mustParseEnvVar() *api.Options {
-	opts := api.DefaultOptions()
-	if os.Getenv(defaultWaitTimeoutEnvVar) != "" {
-		defaultWaitTimeout, err := strconv.ParseFloat(os.Getenv(defaultWaitTimeoutEnvVar), 64)
-		if err != nil {
-			notify.ErrPrint(fmt.Errorf("%s: wrong value: want float got %v", defaultWaitTimeoutEnvVar, err))
-			os.Exit(1)
-		}
-		opts.DefaultWaitTimeout = defaultWaitTimeout
-	}
-	if v, ok := os.LookupEnv(defaultListenPortEnvVar); ok {
-		defaultListener, err := strconv.ParseUint(os.Getenv(defaultListenPortEnvVar), 10, 64)
-		if err != nil {
-			notify.ErrPrint(fmt.Errorf("%s: wrong value: want uint got %v", defaultListenPortEnvVar, err))
-			os.Exit(1)
-		}
-		if defaultListener > 65535 {
-			notify.ErrPrint(fmt.Errorf("%s: wrong value: want uint < 65535 got %v", defaultListenPortEnvVar, defaultListener))
-			os.Exit(1)
-		}
-		opts.DefaultListenPort = v
-	}
-	// checkBoolEnv is a convenience function for reading
-	// an env var with a bool value where
-	// `1` is true and `0` is false.
-	checkBoolEnv := func(name string) bool {
-		if v, ok := os.LookupEnv(name); ok {
-			if v != "1" && v != "0" {
-				notify.ErrPrint(fmt.Errorf("%s: wrong value: want \"0\" or \"1\" got %v", name, v))
-				os.Exit(1)
-			}
-			return v == "1"
-		}
-		return false
-	}
-	opts.EnableChromeEndpoints = !checkBoolEnv(disableGoogleChromeEnvVar)
-	opts.EnableUnoconvEndpoints = !checkBoolEnv(disableUnoconvEnvVar)
-	opts.EnableHealthcheckLogging = !checkBoolEnv(disableHealthcheckLoggingEnvVar)
-	opts.DebugProcessStartup = checkBoolEnv(debugProcessStartup)
-	return opts
-}
-
-func mustStartProcesses(opts *api.Options) []pm2.Process {
-	var processes []pm2.Process
-	if opts.EnableChromeEndpoints {
-		processes = append(processes, pm2.NewChrome(opts.DebugProcessStartup))
-	}
-	if opts.EnableUnoconvEndpoints {
-		processes = append(processes, pm2.NewUnoconv(opts.DebugProcessStartup))
-	}
-	for _, p := range processes {
-		notify.Printf("starting %s with PM2...", p.Fullname())
-		if err := p.Start(); err != nil {
-			notify.ErrPrint(err)
-			os.Exit(1)
-		}
-	}
-	return processes
-}
-
-func mustStartAPI(srv *echo.Echo, port string) {
-	notify.Printf("http server started on port %v", port)
-	if err := srv.Start(fmt.Sprintf(":%v", port)); err != nil {
-		if err != http.ErrServerClosed {
-			notify.ErrPrint(err)
-			os.Exit(1)
-		}
-	}
-}
-
-func mustShutdownProcesses(processes []pm2.Process) {
-	for _, p := range processes {
-		notify.Printf("shutting down %s with PM2... (Ctrl+C to force)", p.Fullname())
-		if err := p.Shutdown(); err != nil {
-			notify.ErrPrint(err)
-			os.Exit(1)
-		}
-	}
-}
-
-func mustShutdownAPI(srv *echo.Echo) {
-	// create a deadline to wait for.
-	ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
-	defer cancel()
-	// doesn't block if no connections, but will otherwise wait
-	// until the timeout deadline.
-	notify.Print("shutting down http server... (Ctrl+C to force)")
-	if err := srv.Shutdown(ctx); err != nil {
-		notify.ErrPrint(err)
-		os.Exit(1)
-	}
-}
-
 func main() {
-	notify.Printf("Gotenberg %s", version)
-	opts := mustParseEnvVar()
-	srv := api.New(opts)
-	processes := mustStartProcesses(opts)
-	// run our API in a goroutine so that it doesn't block.s
+	config, err := conf.FromEnv()
+	systemLogger := log.New(config.LogLevel(), "system")
+	if err != nil {
+		systemLogger.Fatal(err)
+	}
+	systemLogger.Infof("Gotenberg %s", version)
+	// start PM2 processes.
+	var processes []pm2.Process
+	if config.EnableChromeEndpoints() {
+		processes = append(processes, pm2.NewChrome(systemLogger))
+	}
+	if config.EnableUnoconvEndpoints() {
+		processes = append(processes, pm2.NewUnoconv(systemLogger))
+	}
+	for _, p := range processes {
+		systemLogger.Infof("starting %s with PM2...", p.Fullname())
+		if err := p.Start(); err != nil {
+			systemLogger.Fatal(err)
+		}
+	}
+	// run our API in a goroutine so that it doesn't block.
+	// create our API.
+	srv := api.New(config)
 	go func() {
-		mustStartAPI(srv, opts.DefaultListenPort)
+		systemLogger.Infof("http server started on port %s", config.DefaultListenPort())
+		if err := srv.Start(fmt.Sprintf(":%s", config.DefaultListenPort())); err != nil {
+			if err != http.ErrServerClosed {
+				systemLogger.Fatal(err)
+			}
+		}
 	}()
 	quit := make(chan os.Signal, 1)
 	// we'll accept graceful shutdowns when quit via SIGINT (Ctrl+C)
@@ -136,8 +56,22 @@ func main() {
 	signal.Notify(quit, os.Interrupt)
 	// block until we receive our signal.
 	<-quit
-	mustShutdownAPI(srv)
-	mustShutdownProcesses(processes)
-	notify.Print("bye!")
+	// create a deadline to wait for.
+	ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
+	defer cancel()
+	// doesn't block if no connections, but will otherwise wait
+	// until the timeout deadline.
+	systemLogger.Info("shutting down http server...")
+	if err := srv.Shutdown(ctx); err != nil {
+		systemLogger.Fatal(err)
+	}
+	// shutdown PM2 processes.
+	for _, p := range processes {
+		systemLogger.Infof("shutting down %s with PM2...", p.Fullname())
+		if err := p.Shutdown(); err != nil {
+			systemLogger.Fatal(err)
+		}
+	}
+	systemLogger.Info("bye!")
 	os.Exit(0)
 }

go.mod

@@ -3,7 +3,6 @@ module github.com/thecodingmachine/gotenberg
 go 1.12
 
 require (
-	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/google/go-cmp v0.2.0 // indirect
 	github.com/gorilla/websocket v1.4.0 // indirect
 	github.com/labstack/echo/v4 v4.0.0
@@ -14,10 +13,11 @@ require (
 	github.com/microcosm-cc/bluemonday v1.0.1
 	github.com/russross/blackfriday/v2 v2.0.1
 	github.com/shurcooL/sanitized_anchor_name v0.0.0-20170918181015-86672fcb3f95 // indirect
+	github.com/sirupsen/logrus v1.4.2
 	github.com/stretchr/testify v1.3.0
 	github.com/valyala/fasttemplate v1.0.1 // indirect
 	golang.org/x/crypto v0.0.0-20190325154230-a5d413f7728c // indirect
 	golang.org/x/net v0.0.0-20181201002055-351d144fa1fc // indirect
 	golang.org/x/sync v0.0.0-20181108010431-42b317875d0f
-	golang.org/x/sys v0.0.0-20190322080309-f49334f85ddc // indirect
+	golang.org/x/sys v0.0.0-20190621062556-bf70e4678053 // indirect
 )

go.sum

@@ -7,6 +7,8 @@ github.com/google/go-cmp v0.2.0 h1:+dTQ8DZQJz0Mb/HjFlkptS1FeQ4cWSnN941F8aEG4SQ=
 github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5aqRK0M=
 github.com/gorilla/websocket v1.4.0 h1:WDFjx/TMzVgy9VdMMQi2K2Emtwi2QcUQsztZ/zLaH/Q=
 github.com/gorilla/websocket v1.4.0/go.mod h1:E7qHFY5m1UJ88s3WnNqhKjPHQ0heANvMoAMk2YaljkQ=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1 h1:mweAR1A6xJ3oS2pRaGiHgQ4OO8tzTaLawm8vnODuwDk=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/labstack/echo/v4 v4.0.0 h1:q1GH+caIXPP7H2StPIdzy/ez9CO0EepqYeUg6vi9SWM=
 github.com/labstack/echo/v4 v4.0.0/go.mod h1:tZv7nai5buKSg5h/8E6zz4LsD/Dqh9/91Mvs7Z5Zyno=
 github.com/labstack/gommon v0.2.8 h1:JvRqmeZcfrHC5u6uVleB4NxxNbzx6gpbJiQknDbKQu0=
@@ -30,7 +32,11 @@ github.com/russross/blackfriday/v2 v2.0.1 h1:lPqVAte+HuHNfhJ/0LC98ESWRz8afy9tM/0
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/shurcooL/sanitized_anchor_name v0.0.0-20170918181015-86672fcb3f95 h1:/vdW8Cb7EXrkqWGufVMES1OH2sU9gKVb2n9/1y5NMBY=
 github.com/shurcooL/sanitized_anchor_name v0.0.0-20170918181015-86672fcb3f95/go.mod h1:1NzhyTcUVG4SuEtjjoZeVRXNmyL/1OwPU0+IJeTBvfc=
+github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
+github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0Q=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw=
@@ -49,5 +55,6 @@ golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJ
 golang.org/x/sys v0.0.0-20190129075346-302c3dd5f1cc/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-20190322080309-f49334f85ddc h1:4gbWbmmPFp4ySWICouJl6emP0MyS31yy9SrTlAGFT+g=
-golang.org/x/sys v0.0.0-20190322080309-f49334f85ddc/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20190621062556-bf70e4678053 h1:T0MJjz97TtCXa3ZNW2Oenb3KQWB91K965zMEbIJ4ThA=
+golang.org/x/sys v0.0.0-20190621062556-bf70e4678053/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=

internal/app/api/api.go

@@ -1,51 +1,32 @@
 package api
 
-import "github.com/labstack/echo/v4"
+import (
+	"github.com/labstack/echo/v4"
+	conf "github.com/thecodingmachine/gotenberg/internal/pkg/config"
+)
 
 const pingEndpoint = "/ping"
 
-// Options allows to customize the behaviour
-// of the API.
-type Options struct {
-	DefaultWaitTimeout       float64
-	DefaultListenPort        string
-	EnableChromeEndpoints    bool
-	EnableUnoconvEndpoints   bool
-	EnableHealthcheckLogging bool
-	DebugProcessStartup      bool
-}
-
-// DefaultOptions returns default options.
-func DefaultOptions() *Options {
-	return &Options{
-		DefaultWaitTimeout:       10,
-		DefaultListenPort:        "3000",
-		EnableChromeEndpoints:    true,
-		EnableUnoconvEndpoints:   true,
-		EnableHealthcheckLogging: true,
-	}
-}
-
 // New returns an API.
-func New(opts *Options) *echo.Echo {
+func New(config *conf.Config) *echo.Echo {
 	api := echo.New()
 	api.HideBanner = true
 	api.HidePort = true
-	api.Use(handleLogging(opts.EnableHealthcheckLogging))
+	api.Use(contextMiddleware(config))
+	api.Use(loggingMiddleware())
+	api.Use(finalizeMiddleware())
 	api.GET(pingEndpoint, func(c echo.Context) error { return nil })
-	g := api.Group("/convert")
-	g.Use(handleContext(opts))
-	g.Use(handleError())
-	g.POST("/merge", merge)
-	if !opts.EnableChromeEndpoints && !opts.EnableUnoconvEndpoints {
+	api.POST("/merge", merge)
+	if !config.EnableChromeEndpoints() && !config.EnableUnoconvEndpoints() {
 		return api
 	}
-	if opts.EnableChromeEndpoints {
+	g := api.Group("/convert")
+	if config.EnableChromeEndpoints() {
 		g.POST("/html", convertHTML)
 		g.POST("/url", convertURL)
 		g.POST("/markdown", convertMarkdown)
 	}
-	if opts.EnableUnoconvEndpoints {
+	if config.EnableUnoconvEndpoints() {
 		g.POST("/office", convertOffice)
 	}
 	return api

internal/app/api/handler.go

@@ -6,8 +6,8 @@ import (
 	"os"
 
 	"github.com/labstack/echo/v4"
+	"github.com/labstack/gommon/random"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/printer"
-	"github.com/thecodingmachine/gotenberg/internal/pkg/rand"
 )
 
 type errBadRequest struct {
@@ -20,7 +20,7 @@ func (e *errBadRequest) Error() string {
 
 func merge(c echo.Context) error {
 	ctx := c.(*resourceContext)
-	opts, err := ctx.resource.mergePrinterOptions()
+	opts, err := ctx.resource.mergePrinterOptions(ctx.config.DefaultWaitTimeout())
 	if err != nil {
 		return &errBadRequest{err}
 	}
@@ -34,7 +34,7 @@ func merge(c echo.Context) error {
 
 func convertHTML(c echo.Context) error {
 	ctx := c.(*resourceContext)
-	opts, err := ctx.resource.chromePrinterOptions()
+	opts, err := ctx.resource.chromePrinterOptions(ctx.config.DefaultWaitTimeout())
 	if err != nil {
 		return &errBadRequest{err}
 	}
@@ -48,7 +48,7 @@ func convertHTML(c echo.Context) error {
 
 func convertMarkdown(c echo.Context) error {
 	ctx := c.(*resourceContext)
-	opts, err := ctx.resource.chromePrinterOptions()
+	opts, err := ctx.resource.chromePrinterOptions(ctx.config.DefaultWaitTimeout())
 	if err != nil {
 		return &errBadRequest{err}
 	}
@@ -65,7 +65,7 @@ func convertMarkdown(c echo.Context) error {
 
 func convertURL(c echo.Context) error {
 	ctx := c.(*resourceContext)
-	opts, err := ctx.resource.chromePrinterOptions()
+	opts, err := ctx.resource.chromePrinterOptions(ctx.config.DefaultWaitTimeout())
 	if err != nil {
 		return &errBadRequest{err}
 	}
@@ -79,7 +79,7 @@ func convertURL(c echo.Context) error {
 
 func convertOffice(c echo.Context) error {
 	ctx := c.(*resourceContext)
-	opts, err := ctx.resource.officePrinterOptions()
+	opts, err := ctx.resource.officePrinterOptions(ctx.config.DefaultWaitTimeout())
 	if err != nil {
 		return &errBadRequest{err}
 	}
@@ -105,10 +105,7 @@ func convertOffice(c echo.Context) error {
 }
 
 func convert(ctx *resourceContext, p printer.Printer) error {
-	baseFilename, err := rand.Get()
-	if err != nil {
-		return err
-	}
+	baseFilename := random.String(32)
 	filename := fmt.Sprintf("%s.pdf", baseFilename)
 	fpath := fmt.Sprintf("%s/%s", ctx.resource.formFilesDirPath, filename)
 	// if no webhook URL given, run conversion
@@ -118,11 +115,12 @@ func convert(ctx *resourceContext, p printer.Printer) error {
 		if err := p.Print(fpath); err != nil {
 			return err
 		}
-		if ctx.resource.has(resultFilename) {
-			filename, err = ctx.resource.get(resultFilename)
-			if err != nil {
-				return &errBadRequest{err}
-			}
+		if !ctx.resource.has(resultFilename) {
+			return ctx.Attachment(fpath, filename)
+		}
+		filename, err := ctx.resource.get(resultFilename)
+		if err != nil {
+			return &errBadRequest{err}
 		}
 		return ctx.Attachment(fpath, filename)
 	}
@@ -132,23 +130,23 @@ func convert(ctx *resourceContext, p printer.Printer) error {
 	go func() {
 		defer ctx.resource.close() // nolint: errcheck
 		if err := p.Print(fpath); err != nil {
-			ctx.Logger().Error(err)
+			ctx.logger.Error(err)
 			return
 		}
 		f, err := os.Open(fpath)
 		if err != nil {
-			ctx.Logger().Error(err)
+			ctx.logger.Error(err)
 			return
 		}
 		defer f.Close() // nolint: errcheck
 		webhook, err := ctx.resource.get(webhookURL)
 		if err != nil {
-			ctx.Logger().Error(err)
+			ctx.logger.Error(err)
 			return
 		}
 		resp, err := http.Post(webhook, "application/pdf", f) /* #nosec */
 		if err != nil {
-			ctx.Logger().Error(err)
+			ctx.logger.Error(err)
 			return
 		}
 		defer resp.Body.Close() // nolint: errcheck

internal/app/api/middleware.go

@@ -6,70 +6,84 @@ import (
 	"strings"
 
 	"github.com/labstack/echo/v4"
-	"github.com/labstack/echo/v4/middleware"
+	"github.com/labstack/gommon/random"
+	conf "github.com/thecodingmachine/gotenberg/internal/pkg/config"
+	log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
 )
 
-func handleLogging(enableHealthcheckLogging bool) echo.MiddlewareFunc {
-	if enableHealthcheckLogging {
-		// default logging middleware.
-		return middleware.Logger()
-	}
-	// middleware for skipping logging when the ping endpoint is called.
-	return middleware.LoggerWithConfig(middleware.LoggerConfig{
-		Skipper: func(c echo.Context) bool {
-			return c.Request().URL.Path == pingEndpoint
-		},
-	})
-}
-
-func handleContext(opts *Options) echo.MiddlewareFunc {
-	// middleware for extending default context with our
-	// custom constext.
+func contextMiddleware(config *conf.Config) echo.MiddlewareFunc {
+	// middleware for extending the default context
+	// with one of our own context.
 	return func(next echo.HandlerFunc) echo.HandlerFunc {
 		return func(c echo.Context) error {
-			ctx := &resourceContext{c, opts, nil}
-			r, err := newResource(ctx)
-			if err != nil {
-				if resourceErr := r.close(); resourceErr != nil {
-					c.Logger().Error(resourceErr)
+			// generate a unique identifier for our request.
+			trace := random.String(32)
+			// create the logger for this request using
+			// the previous identifier as trace.
+			logger := log.New(config.LogLevel(), trace)
+			// extend the current echo context with our standard
+			// context.
+			ctx := newStandardContext(c, logger, config)
+			// if the endpoint is not for liveness, make a
+			// context with resource.
+			if ctx.Path() != pingEndpoint {
+				ctx, err := ctx.withResource(trace)
+				if err != nil {
+					ctx.Error(err)
+					return ctx.logEndOfRequest(err)
 				}
-				return err
 			}
-			ctx.resource = r
 			return next(ctx)
 		}
 	}
 }
 
-func handleError() echo.MiddlewareFunc {
-	// middleware for handling errors and removing resources
-	// once the request has been handled.
+func loggingMiddleware() echo.MiddlewareFunc {
+	// middleware for enabling logging.
 	return func(next echo.HandlerFunc) echo.HandlerFunc {
 		return func(c echo.Context) error {
-			err := next(c)
-			ctx := c.(*resourceContext)
-			// if a webhookURL has been given,
-			// do not remove the resources here because
-			// we don't know if the result file has been
-			// generated or sent.
-			if !ctx.resource.has(webhookURL) {
-				if resourceErr := ctx.resource.close(); resourceErr != nil {
-					c.Logger().Error(resourceErr)
-				}
-			}
+			ctx := c.(*standardContext)
+			err := next(ctx)
 			if err != nil {
-				if _, ok := err.(*echo.HTTPError); ok {
-					return err
-				}
-				if _, ok := err.(*errBadRequest); ok {
-					return echo.NewHTTPError(http.StatusBadRequest, err.Error())
-				}
-				if strings.Contains(err.Error(), context.DeadlineExceeded.Error()) {
-					return echo.NewHTTPError(http.StatusRequestTimeout)
-				}
-				return echo.NewHTTPError(http.StatusInternalServerError, err.Error())
+				ctx.Error(err)
 			}
-			return nil
+			return ctx.logEndOfRequest(err)
+		}
+	}
+}
+
+func finalizeMiddleware() echo.MiddlewareFunc {
+	// middleware for removing resources at the end of a request
+	// and for improving response in case of error.
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c echo.Context) error {
+			err := next(c)
+			ctx, ok := c.(*resourceContext)
+			// a resource is associated with the context.
+			if ok {
+				// if a webhookURL has been given,
+				// do not remove the resources here because
+				// we don't know if the result file has been
+				// generated or sent.
+				if !ctx.resource.has(webhookURL) {
+					if resourceErr := ctx.resource.close(); resourceErr != nil {
+						ctx.logger.Error(err)
+					}
+				}
+			}
+			if err == nil {
+				return nil
+			}
+			if _, ok := err.(*echo.HTTPError); ok {
+				return err
+			}
+			if _, ok := err.(*errBadRequest); ok {
+				return echo.NewHTTPError(http.StatusBadRequest, err.Error())
+			}
+			if strings.Contains(err.Error(), context.DeadlineExceeded.Error()) {
+				return echo.NewHTTPError(http.StatusRequestTimeout, err.Error())
+			}
+			return echo.NewHTTPError(http.StatusInternalServerError, err.Error())
 		}
 	}
 }

internal/app/api/resource.go

@@ -10,7 +10,6 @@ import (
 
 	"github.com/labstack/echo/v4"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/printer"
-	"github.com/thecodingmachine/gotenberg/internal/pkg/rand"
 )
 
 const (
@@ -31,53 +30,41 @@ const (
 type resource struct {
 	formValues       map[string]string
 	formFilesDirPath string
-	opts             *Options
 }
 
-type resourceContext struct {
-	echo.Context
-	opts     *Options
-	resource *resource
-}
-
-func newResource(ctx *resourceContext) (*resource, error) {
+func newResource(c echo.Context, dirPath string) (*resource, error) {
 	r := &resource{
-		formValues: formValues(ctx),
-		opts:       ctx.opts,
-	}
-	dirPath, err := rand.Get()
-	if err != nil {
-		return r, err
+		formValues: formValues(c),
 	}
 	r.formFilesDirPath = dirPath
 	if err := os.MkdirAll(dirPath, 0755); err != nil {
 		return nil, fmt.Errorf("%s: making directory: %v", dirPath, err)
 	}
-	if err := formFiles(ctx, dirPath); err != nil {
+	if err := formFiles(c, dirPath); err != nil {
 		return r, err
 	}
 	return r, nil
 }
 
-func formValues(ctx *resourceContext) map[string]string {
+func formValues(c echo.Context) map[string]string {
 	v := make(map[string]string)
-	v[resultFilename] = ctx.FormValue(resultFilename)
-	v[waitTimeout] = ctx.FormValue(waitTimeout)
-	v[webhookURL] = ctx.FormValue(webhookURL)
-	v[remoteURL] = ctx.FormValue(remoteURL)
-	v[waitDelay] = ctx.FormValue(waitDelay)
-	v[paperWidth] = ctx.FormValue(paperWidth)
-	v[paperHeight] = ctx.FormValue(paperHeight)
-	v[marginTop] = ctx.FormValue(marginTop)
-	v[marginBottom] = ctx.FormValue(marginBottom)
-	v[marginLeft] = ctx.FormValue(marginLeft)
-	v[marginRight] = ctx.FormValue(marginRight)
-	v[landscape] = ctx.FormValue(landscape)
+	v[resultFilename] = c.FormValue(resultFilename)
+	v[waitTimeout] = c.FormValue(waitTimeout)
+	v[webhookURL] = c.FormValue(webhookURL)
+	v[remoteURL] = c.FormValue(remoteURL)
+	v[waitDelay] = c.FormValue(waitDelay)
+	v[paperWidth] = c.FormValue(paperWidth)
+	v[paperHeight] = c.FormValue(paperHeight)
+	v[marginTop] = c.FormValue(marginTop)
+	v[marginBottom] = c.FormValue(marginBottom)
+	v[marginLeft] = c.FormValue(marginLeft)
+	v[marginRight] = c.FormValue(marginRight)
+	v[landscape] = c.FormValue(landscape)
 	return v
 }
 
-func formFiles(ctx *resourceContext, dirPath string) error {
-	form, err := ctx.MultipartForm()
+func formFiles(c echo.Context, dirPath string) error {
+	form, err := c.MultipartForm()
 	if err != nil {
 		return fmt.Errorf("getting multipart form: %v", err)
 	}
@@ -117,8 +104,8 @@ func (r *resource) close() error {
 
 const defaultHeaderFooterHTML string = "<html><head></head><body></body></html>"
 
-func (r *resource) chromePrinterOptions() (*printer.ChromeOptions, error) {
-	timeout, err := r.float64(waitTimeout, r.opts.DefaultWaitTimeout)
+func (r *resource) chromePrinterOptions(defaultWaitTimeout float64) (*printer.ChromeOptions, error) {
+	timeout, err := r.float64(waitTimeout, defaultWaitTimeout)
 	if err != nil {
 		return nil, err
 	}
@@ -177,8 +164,8 @@ func (r *resource) chromePrinterOptions() (*printer.ChromeOptions, error) {
 	}, nil
 }
 
-func (r *resource) officePrinterOptions() (*printer.OfficeOptions, error) {
-	timeout, err := r.float64(waitTimeout, r.opts.DefaultWaitTimeout)
+func (r *resource) officePrinterOptions(defaultWaitTimeout float64) (*printer.OfficeOptions, error) {
+	timeout, err := r.float64(waitTimeout, defaultWaitTimeout)
 	if err != nil {
 		return nil, err
 	}
@@ -192,8 +179,8 @@ func (r *resource) officePrinterOptions() (*printer.OfficeOptions, error) {
 	}, nil
 }
 
-func (r *resource) mergePrinterOptions() (*printer.MergeOptions, error) {
-	timeout, err := r.float64(waitTimeout, r.opts.DefaultWaitTimeout)
+func (r *resource) mergePrinterOptions(defaultWaitTimeout float64) (*printer.MergeOptions, error) {
+	timeout, err := r.float64(waitTimeout, defaultWaitTimeout)
 	if err != nil {
 		return nil, err
 	}

internal/pkg/notify/doc.go

@@ -1,5 +0,0 @@
-/*
-Package notify helps displaying nice outputs
-to the user.
-*/
-package notify

internal/pkg/notify/notify.go

@@ -1,35 +0,0 @@
-package notify
-
-import (
-	"fmt"
-	"os"
-
-	"github.com/labstack/gommon/color"
-)
-
-// Print prints a message to stdout.
-func Print(message string) {
-	stdout := color.New()
-	stdout.SetOutput(os.Stdout)
-	stdout.Printf("⇨ %s\n", message)
-}
-
-// Printf prints a formatted message to stdout.
-func Printf(format string, a ...interface{}) {
-	message := fmt.Sprintf(format, a...)
-	Print(message)
-}
-
-// WarnPrint prints a warning to stderr.
-func WarnPrint(err error) {
-	stderr := color.New()
-	stderr.SetOutput(os.Stderr)
-	stderr.Printf("%s\n", color.Yellow(fmt.Sprintf("⇨ warn: %v", err)))
-}
-
-// ErrPrint prints an error to stderr.
-func ErrPrint(err error) {
-	stderr := color.New()
-	stderr.SetOutput(os.Stderr)
-	stderr.Printf("%s\n", color.Red(fmt.Sprintf("⇨ error: %v", err)))
-}

internal/pkg/pm2/chrome.go

@@ -5,6 +5,7 @@ import (
 	"time"
 
 	"github.com/mafredri/cdp/devtool"
+	log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
 )
 
 const warmupTime = 10 * time.Second
@@ -15,9 +16,9 @@ type chrome struct {
 
 // NewChrome returns a Google Chrome
 // headless process.
-func NewChrome(debug bool) Process {
+func NewChrome(logger *log.StandardLogger) Process {
 	return &chrome{
-		manager: &processManager{verbose: debug},
+		manager: &processManager{logger: logger},
 	}
 }
 
@@ -60,19 +61,18 @@ func (p *chrome) viable() bool {
 	// check if Google Chrome is correctly running.
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
-	p.manager.notifyf(`%v: checking Chrome liveness via debug version endpoint 
-'http://localhost:9222/json/version'`, p.name())
+	p.manager.logger.Debugf("%s: checking liveness via debug version endpoint http://localhost:9222/json/version", p.Fullname())
 	v, err := devtool.New("http://localhost:9222").Version(ctx)
 	if err != nil {
-		p.manager.notifyf("%s: %s version endpoint returned error: %v", p.name(), p.Fullname(), err)
+		p.manager.logger.Debugf("%s: debug version endpoint returned error: %v", p.Fullname(), err)
 		return false
 	}
-	p.manager.notifyf("%s: %s returned version info: %+v", p.name(), p.Fullname(), *v)
+	p.manager.logger.Debugf("%s: debug version endpoint returned version info: %+v", p.Fullname(), *v)
 	return true
 }
 
 func (p *chrome) warmup() {
-	p.manager.notifyf("%s: allowing %s %v to startup", p.name(), p.Fullname(), warmupTime)
+	p.manager.logger.Debugf("%s: allowing %v to startup", p.Fullname(), warmupTime)
 	time.Sleep(warmupTime)
 }
 

internal/pkg/pm2/pm2.go

@@ -6,9 +6,8 @@ import (
 	"io"
 	"os/exec"
 	"strings"
-	"time"
 
-	"github.com/thecodingmachine/gotenberg/internal/pkg/notify"
+	log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
 )
 
 const (
@@ -31,7 +30,7 @@ type Process interface {
 
 type processManager struct {
 	heuristicState int32
-	verbose        bool
+	logger         *log.StandardLogger
 }
 
 func (m *processManager) start(p Process) error {
@@ -83,43 +82,35 @@ func (m *processManager) pm2(p Process, cmdName string) error {
 		"pm2",
 		cmdArgs...,
 	)
-	m.notifyf("executing command '%v'", strings.Join(cmd.Args, " "))
-	if m.verbose {
-		processStdErr, err := cmd.StderrPipe()
-		if err != nil {
-			return fmt.Errorf("failed getting stderr from %s: %s", p.Fullname(), err)
-		}
-		processStdOut, err := cmd.StdoutPipe()
-		if err != nil {
-			return fmt.Errorf("failed getting stdout from %s: %s", p.Fullname(), err)
-		}
-		readFromPipe := func(name string, reader io.ReadCloser) {
-			r := bufio.NewReader(reader)
-			defer reader.Close() // nolint: errcheck
-			for {
-				line, _, err := r.ReadLine()
-				if err != nil {
-					if err != io.EOF {
-						m.notifyf("error reading from %s for process %s", name, p.Fullname())
-					}
-					break
-				}
-				if len(line) != 0 {
-					m.notifyf("%s %s: %s", p.name(), name, string(line))
+	m.logger.Debugf("executing command: %v", strings.Join(cmd.Args, " "))
+	processStdOut, err := cmd.StdoutPipe()
+	if err != nil {
+		return fmt.Errorf("failed getting stdout from %s: %s", p.Fullname(), err)
+	}
+	processStdErr, err := cmd.StderrPipe()
+	if err != nil {
+		return fmt.Errorf("failed getting stderr from %s: %s", p.Fullname(), err)
+	}
+	readFromPipe := func(outputType string, reader io.ReadCloser) {
+		r := bufio.NewReader(reader)
+		defer reader.Close() // nolint: errcheck
+		for {
+			line, _, err := r.ReadLine()
+			if err != nil {
+				if err != io.EOF {
+					m.logger.Errorf("error reading from %s for process %s", outputType, p.Fullname())
 				}
+				break
+			}
+			if len(line) != 0 {
+				m.logger.Debugf("%s %s: %s", p.Fullname(), outputType, string(line))
 			}
 		}
-		go readFromPipe("stdout", processStdOut)
-		go readFromPipe("stderr", processStdErr)
 	}
+	go readFromPipe("stdout", processStdOut)
+	go readFromPipe("stderr", processStdErr)
 	if err := cmd.Start(); err != nil {
 		return fmt.Errorf("%s %s with PM2: %v", cmdName, p.Fullname(), err)
 	}
 	return nil
 }
-
-func (m *processManager) notifyf(format string, args ...interface{}) {
-	if m.verbose {
-		notify.Printf(fmt.Sprintf("%v: %s", time.Now().Format(time.RFC3339), format), args...)
-	}
-}

internal/pkg/pm2/unoconv.go

@@ -1,14 +1,18 @@
 package pm2
 
+import (
+	log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
+)
+
 type unoconv struct {
 	manager *processManager
 }
 
 // NewUnoconv returns a unoconv listener
 // process.
-func NewUnoconv(debug bool) Process {
+func NewUnoconv(logger *log.StandardLogger) Process {
 	return &unoconv{
-		manager: &processManager{verbose: debug},
+		manager: &processManager{logger: logger},
 	}
 }
 

internal/pkg/printer/markdown.go

@@ -7,9 +7,9 @@ import (
 	"io/ioutil"
 	"path/filepath"
 
+	"github.com/labstack/gommon/random"
 	"github.com/microcosm-cc/bluemonday"
 	"github.com/russross/blackfriday/v2"
-	"github.com/thecodingmachine/gotenberg/internal/pkg/rand"
 )
 
 // NewMarkdown returns a Markdown printer.
@@ -27,10 +27,7 @@ func NewMarkdown(fpath string, opts *ChromeOptions) (Printer, error) {
 	if err := tmpl.Execute(&buffer, data); err != nil {
 		return nil, fmt.Errorf("%s: executing template: %v", fpath, err)
 	}
-	baseFilename, err := rand.Get()
-	if err != nil {
-		return nil, err
-	}
+	baseFilename := random.String(32)
 	dst := fmt.Sprintf("%s/%s.html", dirPath, baseFilename)
 	if err := ioutil.WriteFile(dst, buffer.Bytes(), 0644); err != nil {
 		return nil, fmt.Errorf("%s: writing file: %v", dst, err)

internal/pkg/printer/office.go

@@ -9,7 +9,7 @@ import (
 	"sync"
 	"time"
 
-	"github.com/thecodingmachine/gotenberg/internal/pkg/rand"
+	"github.com/labstack/gommon/random"
 )
 
 type office struct {
@@ -38,10 +38,7 @@ func (p *office) Print(destination string) error {
 	fpaths := make([]string, len(p.fpaths))
 	dirPath := filepath.Dir(destination)
 	for i, fpath := range p.fpaths {
-		baseFilename, err := rand.Get()
-		if err != nil {
-			return err
-		}
+		baseFilename := random.String(32)
 		tmpDest := fmt.Sprintf("%s/%d%s.pdf", dirPath, i, baseFilename)
 		if err := unoconv(ctx, fpath, tmpDest, p.opts); err != nil {
 			return err

internal/pkg/rand/doc.go

@@ -1,7 +0,0 @@
-/*
-Package rand helps generating a random string.
-
-It should be used for creating directory and
-file names in order to avoid collision.
-*/
-package rand

internal/pkg/rand/rand.go

@@ -1,17 +0,0 @@
-package rand
-
-import (
-	"crypto/rand"
-	"encoding/hex"
-	"fmt"
-)
-
-// Get returns a random string.
-func Get() (string, error) {
-	randBytes := make([]byte, 16)
-	_, err := rand.Read(randBytes)
-	if err != nil {
-		return "", fmt.Errorf("creating random string: %v", err)
-	}
-	return hex.EncodeToString(randBytes), nil
-}

internal/pkg/rand/rand_test.go

@@ -1,16 +0,0 @@
-package rand
-
-import (
-	"testing"
-
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
-)
-
-func TestGet(t *testing.T) {
-	rand1, err := Get()
-	require.Nil(t, err)
-	rand2, err := Get()
-	require.Nil(t, err)
-	assert.NotEqual(t, rand1, rand2)
-}