From 70b185a37a809c3fb69a2ad25640a61cf86436e5 Mon Sep 17 00:00:00 2001
From: Julien Neuhart <j.neuhart@thecodingmachine.com>
Date: Mon, 8 Jul 2019 11:06:26 +0200
Subject: [PATCH] improving logging

---
 cmd/gotenberg/main.go                      |  1 +
 internal/app/api/pkg/handler/html.go       |  1 +
 internal/app/api/pkg/handler/markdown.go   |  1 +
 internal/app/api/pkg/handler/merge.go      |  1 +
 internal/app/api/pkg/handler/office.go     |  1 +
 internal/app/api/pkg/handler/url.go        |  1 +
 internal/app/api/pkg/middleware/context.go |  3 +-
 internal/app/api/pkg/middleware/error.go   |  3 +-
 internal/app/api/pkg/resource/resource.go  | 43 +++++++++++++---------
 internal/pkg/pm2/chrome.go                 | 10 ++---
 internal/pkg/pm2/unoconv.go                | 12 +++++-
 11 files changed, 49 insertions(+), 28 deletions(-)

diff --git a/cmd/gotenberg/main.go b/cmd/gotenberg/main.go
index 28a8e976..92131b52 100644
--- a/cmd/gotenberg/main.go
+++ b/cmd/gotenberg/main.go
@@ -26,6 +26,7 @@ func main() {
 		systemLogger.FatalOp(op, err)
 	}
 	systemLogger.InfofOp(op, "Gotenberg %s", version)
+	systemLogger.DebugfOp(op, "configuration: %+v", config)
 	// start PM2 processes.
 	var processes []pm2.Process
 	if config.EnableChromeEndpoints() {
diff --git a/internal/app/api/pkg/handler/html.go b/internal/app/api/pkg/handler/html.go
index 117e1749..eb1581bb 100644
--- a/internal/app/api/pkg/handler/html.go
+++ b/internal/app/api/pkg/handler/html.go
@@ -12,6 +12,7 @@ import (
 func HTML(c echo.Context) error {
 	const op = "handler.HTML"
 	ctx := context.MustCastFromEchoContext(c)
+	ctx.StandardLogger().DebugfOp(op, "html request")
 	r := ctx.Resource()
 	opts, err := r.ChromePrinterOptions()
 	if err != nil {
diff --git a/internal/app/api/pkg/handler/markdown.go b/internal/app/api/pkg/handler/markdown.go
index 6e22a556..a7f59379 100644
--- a/internal/app/api/pkg/handler/markdown.go
+++ b/internal/app/api/pkg/handler/markdown.go
@@ -12,6 +12,7 @@ import (
 func Markdown(c echo.Context) error {
 	const op = "handler.Markdown"
 	ctx := context.MustCastFromEchoContext(c)
+	ctx.StandardLogger().DebugfOp(op, "markdown request")
 	r := ctx.Resource()
 	opts, err := r.ChromePrinterOptions()
 	if err != nil {
diff --git a/internal/app/api/pkg/handler/merge.go b/internal/app/api/pkg/handler/merge.go
index 6bd74d27..381e7da2 100644
--- a/internal/app/api/pkg/handler/merge.go
+++ b/internal/app/api/pkg/handler/merge.go
@@ -12,6 +12,7 @@ import (
 func Merge(c echo.Context) error {
 	const op = "handler.Merge"
 	ctx := context.MustCastFromEchoContext(c)
+	ctx.StandardLogger().DebugfOp(op, "merge request")
 	r := ctx.Resource()
 	opts, err := r.MergePrinterOptions()
 	if err != nil {
diff --git a/internal/app/api/pkg/handler/office.go b/internal/app/api/pkg/handler/office.go
index 09d294b4..60ccca1c 100644
--- a/internal/app/api/pkg/handler/office.go
+++ b/internal/app/api/pkg/handler/office.go
@@ -12,6 +12,7 @@ import (
 func Office(c echo.Context) error {
 	const op = "handler.Office"
 	ctx := context.MustCastFromEchoContext(c)
+	ctx.StandardLogger().DebugfOp(op, "office request")
 	r := ctx.Resource()
 	opts, err := r.OfficePrinterOptions()
 	if err != nil {
diff --git a/internal/app/api/pkg/handler/url.go b/internal/app/api/pkg/handler/url.go
index f38eda0a..f7383a3c 100644
--- a/internal/app/api/pkg/handler/url.go
+++ b/internal/app/api/pkg/handler/url.go
@@ -13,6 +13,7 @@ import (
 func URL(c echo.Context) error {
 	const op = "handler.URL"
 	ctx := context.MustCastFromEchoContext(c)
+	ctx.StandardLogger().DebugfOp(op, "url request")
 	r := ctx.Resource()
 	opts, err := r.ChromePrinterOptions()
 	if err != nil {
diff --git a/internal/app/api/pkg/middleware/context.go b/internal/app/api/pkg/middleware/context.go
index 29dc26c0..c711683b 100644
--- a/internal/app/api/pkg/middleware/context.go
+++ b/internal/app/api/pkg/middleware/context.go
@@ -30,8 +30,7 @@ func Context(config *config.Config) echo.MiddlewareFunc {
 			// if the endpoint is not for healthcheck, associate a
 			// resource to our custom context.
 			if err := ctx.WithResource(trace); err != nil {
-				// required to have a correct status code
-				// in the logs.
+				// required to have a correct status code.
 				ctx.Error(err)
 				return ctx.LogRequestResult(err, false)
 			}
diff --git a/internal/app/api/pkg/middleware/error.go b/internal/app/api/pkg/middleware/error.go
index 48928e26..876459db 100644
--- a/internal/app/api/pkg/middleware/error.go
+++ b/internal/app/api/pkg/middleware/error.go
@@ -35,8 +35,7 @@ func Error() echo.MiddlewareFunc {
 			default:
 				httpErr = echo.NewHTTPError(http.StatusInternalServerError, errMessage)
 			}
-			// required to have a correct status code
-			// in the logs.
+			// required to have a correct status code.
 			ctx.Error(httpErr)
 			return httpErr
 		}
diff --git a/internal/app/api/pkg/resource/resource.go b/internal/app/api/pkg/resource/resource.go
index 479eb38d..69eb487a 100644
--- a/internal/app/api/pkg/resource/resource.go
+++ b/internal/app/api/pkg/resource/resource.go
@@ -85,19 +85,27 @@ func New(c echo.Context, logger *logger.Logger, config *config.Config, dirPath s
 func formValues(c echo.Context, logger *logger.Logger) map[string]string {
 	const op = "resource.formValues"
 	v := make(map[string]string)
-	v[ResultFilenameFormField] = c.FormValue(ResultFilenameFormField)
-	v[WaitTimeoutFormField] = c.FormValue(WaitTimeoutFormField)
-	v[WebhookURLFormField] = c.FormValue(WebhookURLFormField)
-	v[RemoteURLFormField] = c.FormValue(RemoteURLFormField)
-	v[WaitDelayFormField] = c.FormValue(WaitDelayFormField)
-	v[PaperWidthFormField] = c.FormValue(PaperWidthFormField)
-	v[PaperHeightFormField] = c.FormValue(PaperHeightFormField)
-	v[MarginTopFormField] = c.FormValue(MarginTopFormField)
-	v[MarginBottomFormField] = c.FormValue(MarginBottomFormField)
-	v[MarginLeftFormField] = c.FormValue(MarginLeftFormField)
-	v[MarginRightFormField] = c.FormValue(MarginRightFormField)
-	v[LandscapeFormField] = c.FormValue(LandscapeFormField)
-	logger.DebugfOp(op, "%v", v)
+	fetch := func(formField string) string {
+		value := c.FormValue(formField)
+		if value == "" {
+			logger.DebugfOp(op, "'%s' is empty", formField)
+			return value
+		}
+		logger.DebugfOp(op, "'%s' retrieved, got '%s'", formField, value)
+		return value
+	}
+	v[ResultFilenameFormField] = fetch(ResultFilenameFormField)
+	v[WaitTimeoutFormField] = fetch(WaitTimeoutFormField)
+	v[WebhookURLFormField] = fetch(WebhookURLFormField)
+	v[RemoteURLFormField] = fetch(RemoteURLFormField)
+	v[WaitDelayFormField] = fetch(WaitDelayFormField)
+	v[PaperWidthFormField] = fetch(PaperWidthFormField)
+	v[PaperHeightFormField] = fetch(PaperHeightFormField)
+	v[MarginTopFormField] = fetch(MarginTopFormField)
+	v[MarginBottomFormField] = fetch(MarginBottomFormField)
+	v[MarginLeftFormField] = fetch(MarginLeftFormField)
+	v[MarginRightFormField] = fetch(MarginRightFormField)
+	v[LandscapeFormField] = fetch(LandscapeFormField)
 	return v
 }
 
@@ -221,7 +229,7 @@ func (r *Resource) ChromePrinterOptions() (*printer.ChromeOptions, error) {
 		MarginRight:  marginRight,
 		Landscape:    landscape,
 	}
-	r.logger.DebugfOp(op, "%v", opts)
+	r.logger.DebugfOp(op, "printer options: %+v", opts)
 	return opts, nil
 }
 
@@ -242,7 +250,7 @@ func (r *Resource) OfficePrinterOptions() (*printer.OfficeOptions, error) {
 		WaitTimeout: waitTimeout,
 		Landscape:   landscape,
 	}
-	r.logger.DebugfOp(op, "%v", opts)
+	r.logger.DebugfOp(op, "printer options: %+v", opts)
 	return opts, nil
 }
 
@@ -258,7 +266,7 @@ func (r *Resource) MergePrinterOptions() (*printer.MergeOptions, error) {
 	opts := &printer.MergeOptions{
 		WaitTimeout: waitTimeout,
 	}
-	r.logger.DebugfOp(op, "%v", opts)
+	r.logger.DebugfOp(op, "printer options: %+v", opts)
 	return opts, nil
 }
 
@@ -384,13 +392,12 @@ func (r *Resource) Fpaths(exts ...string) ([]string, error) {
 	const op = "resource.Fpaths"
 	var fpaths []string
 	err := filepath.Walk(r.formFilesDirPath, func(path string, info os.FileInfo, _ error) error {
-		const walkOp = "resource.filepath.Walk"
 		if info.IsDir() {
 			return nil
 		}
 		fpath, err := r.Fpath(info.Name())
 		if err != nil {
-			return &standarderror.Error{Op: walkOp, Err: err}
+			return &standarderror.Error{Op: op, Err: err}
 		}
 		for _, ext := range exts {
 			if filepath.Ext(fpath) == ext {
diff --git a/internal/pkg/pm2/chrome.go b/internal/pkg/pm2/chrome.go
index 120baa50..94492ede 100644
--- a/internal/pkg/pm2/chrome.go
+++ b/internal/pkg/pm2/chrome.go
@@ -9,7 +9,7 @@ import (
 	"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
 )
 
-const warmupTime = 10 * time.Second
+const chromeWarmupTime = 10 * time.Second
 
 type chrome struct {
 	manager *processManager
@@ -93,13 +93,13 @@ func (p *chrome) viable() bool {
 }
 
 func (p *chrome) warmup() {
-	const debugOp = "pm2.chrome.warmup"
+	const op = "pm2.chrome.warmup"
 	p.manager.logger.DebugfOp(
-		debugOp,
+		op,
 		"allowing %v to startup",
-		warmupTime,
+		chromeWarmupTime,
 	)
-	time.Sleep(warmupTime)
+	time.Sleep(chromeWarmupTime)
 }
 
 // Compile-time checks to ensure type implements desired interfaces.
diff --git a/internal/pkg/pm2/unoconv.go b/internal/pkg/pm2/unoconv.go
index 48ec164d..ab1f9cde 100644
--- a/internal/pkg/pm2/unoconv.go
+++ b/internal/pkg/pm2/unoconv.go
@@ -1,10 +1,14 @@
 package pm2
 
 import (
+	"time"
+
 	"github.com/thecodingmachine/gotenberg/internal/pkg/logger"
 	"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
 )
 
+const unoconvWarmupTime = 5 * time.Second
+
 type unoconv struct {
 	manager *processManager
 }
@@ -56,7 +60,13 @@ func (p *unoconv) viable() bool {
 }
 
 func (p *unoconv) warmup() {
-	// let's do nothing.
+	const op = "pm2.unoconv.warmup"
+	p.manager.logger.DebugfOp(
+		op,
+		"allowing %v to startup",
+		unoconvWarmupTime,
+	)
+	time.Sleep(unoconvWarmupTime)
 }
 
 // Compile-time checks to ensure type implements desired interfaces.