all logs now have an op field

This commit is contained in:
Julien Neuhart
2019-07-07 19:54:44 +02:00
parent c8f7ea934c
commit 5f6ab2fc08
16 changed files with 240 additions and 85 deletions

View File

@@ -22,7 +22,7 @@ RUN curl -sfL https://install.goreleaser.com/github.com/golangci/golangci-lint.s
# | Last instructions of this build.
# |
# Define our workding outside of $GOPATH (we're using go modules).
# Define our working directory outside of $GOPATH (we're using go modules).
WORKDIR /lint
# Copy our module dependencies definitions.

View File

@@ -35,7 +35,7 @@ ENV PATH $GOPATH/bin:/usr/local/go/bin:$PATH
# | Last instructions of this build.
# |
# Define our workding outside of $GOPATH (we're using go modules).
# Define our working directory outside of $GOPATH (we're using go modules).
WORKDIR /tests
# Copy our module dependencies definitions.

View File

@@ -9,8 +9,8 @@ import (
"time"
"github.com/thecodingmachine/gotenberg/internal/app/api"
conf "github.com/thecodingmachine/gotenberg/internal/pkg/config"
log "github.com/thecodingmachine/gotenberg/internal/pkg/logger"
"github.com/thecodingmachine/gotenberg/internal/pkg/config"
"github.com/thecodingmachine/gotenberg/internal/pkg/logger"
"github.com/thecodingmachine/gotenberg/internal/pkg/pm2"
)
@@ -19,12 +19,13 @@ import (
var version = "snapshot"
func main() {
config, err := conf.FromEnv()
systemLogger := log.New(config.LogLevel(), "system")
const op = "main"
config, err := config.FromEnv()
systemLogger := logger.New(config.LogLevel(), "system")
if err != nil {
systemLogger.Fatal(err)
systemLogger.FatalOp(op, err)
}
systemLogger.Infof("Gotenberg %s", version)
systemLogger.InfofOp(op, "Gotenberg %s", version)
// start PM2 processes.
var processes []pm2.Process
if config.EnableChromeEndpoints() {
@@ -34,19 +35,19 @@ func main() {
processes = append(processes, pm2.NewUnoconv(systemLogger))
}
for _, p := range processes {
systemLogger.Infof("starting %s with PM2...", p.Fullname())
systemLogger.InfofOp(op, "starting %s with PM2...", p.Fullname())
if err := p.Start(); err != nil {
systemLogger.Fatal(err)
systemLogger.FatalOp(op, err)
}
}
// run our API in a goroutine so that it doesn't block.
// create our API.
srv := api.New(config)
go func() {
systemLogger.Infof("http server started on port %s", config.DefaultListenPort())
systemLogger.InfofOp(op, "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)
systemLogger.FatalOp(op, err)
}
}
}()
@@ -61,17 +62,17 @@ func main() {
defer cancel()
// doesn't block if no connections, but will otherwise wait
// until the timeout deadline.
systemLogger.Info("shutting down http server...")
systemLogger.InfofOp(op, "shutting down http server...")
if err := srv.Shutdown(ctx); err != nil {
systemLogger.Fatal(err)
systemLogger.FatalOp(op, err)
}
// shutdown PM2 processes.
for _, p := range processes {
systemLogger.Infof("shutting down %s with PM2...", p.Fullname())
systemLogger.InfofOp(op, "shutting down %s with PM2...", p.Fullname())
if err := p.Shutdown(); err != nil {
systemLogger.Fatal(err)
systemLogger.FatalOp(op, err)
}
}
systemLogger.Info("bye!")
systemLogger.InfofOp(op, "bye!")
os.Exit(0)
}

1
go.mod
View File

@@ -9,6 +9,7 @@ require (
github.com/labstack/echo/v4 v4.1.6
github.com/labstack/gommon v0.2.9
github.com/mafredri/cdp v0.23.4
github.com/mattn/go-isatty v0.0.8
github.com/microcosm-cc/bluemonday v1.0.2
github.com/russross/blackfriday/v2 v2.0.1
github.com/shurcooL/sanitized_anchor_name v1.0.0 // indirect

View File

@@ -74,11 +74,11 @@ func (ctx *Context) WithResource(resourceDirPath string) error {
// LogRequestResult logs the result of a request.
// This method should only be used by a middleware!
func (ctx *Context) LogRequestResult(err error, isDebug bool) error {
const op = "context.LogRequestResult"
req := ctx.Request()
resp := ctx.Response()
stopTime := time.Now()
fields := map[string]interface{}{
"time_rfc3339": timeRFC3339(), // FIXME required?
"remote_ip": ctx.RealIP(),
"host": req.Host,
"uri": req.RequestURI,
@@ -93,21 +93,17 @@ func (ctx *Context) LogRequestResult(err error, isDebug bool) error {
"bytes_out": bytesOut(resp),
}
if err != nil {
ctx.logger.WithFields(fields).Error("request failed")
ctx.logger.WithFields(fields).ErrorfOp(op, "request failed")
return err
}
if isDebug {
ctx.logger.WithFields(fields).Debug("request handled")
ctx.logger.WithFields(fields).DebugfOp(op, "request handled")
return nil
}
ctx.logger.WithFields(fields).Info("request handled")
ctx.logger.WithFields(fields).InfofOp(op, "request handled")
return nil
}
func timeRFC3339() string {
return time.Now().Format(time.RFC3339)
}
func path(r *http.Request) string {
path := r.URL.Path
if path == "" {

View File

@@ -20,8 +20,9 @@ func Error() echo.MiddlewareFunc {
}
// we log the initial error before returning
// the HTTP error.
errOp := standarderror.Op(err)
logger := ctx.StandardLogger()
logger.Error(err.Error())
logger.ErrorOp(errOp, err)
// handle our custom HTTP error.
var httpErr error
errCode := standarderror.Code(err)

View File

@@ -318,7 +318,7 @@ func (r *Resource) float64(formField string, defaultValue float64) (float64, err
if err != nil {
return 0.0, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not a float", formField),
Message: fmt.Sprintf("'%s' is not a float, got '%s'", formField, v),
Op: op,
}
}
@@ -338,7 +338,7 @@ func (r *Resource) bool(formField string, defaultValue bool) (bool, error) {
if err != nil {
return false, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not a boolean", formField),
Message: fmt.Sprintf("'%s' is not a boolean, got '%s'", formField, v),
Op: op,
}
}

View File

@@ -5,7 +5,8 @@ import (
"os"
"strconv"
log "github.com/sirupsen/logrus"
"github.com/sirupsen/logrus"
"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
)
const (
@@ -16,12 +17,14 @@ const (
logLevelEnvVar = "LOG_LEVEL"
)
// Config contains the application
// configuration.
type Config struct {
defaultWaitTimeout float64
defaultListenPort string
enableChromeEndpoints bool
enableUnoconvEndpoints bool
logLevel log.Level
logLevel logrus.Level
}
func defaultConfig() *Config {
@@ -30,51 +33,85 @@ func defaultConfig() *Config {
defaultListenPort: "3000",
enableChromeEndpoints: true,
enableUnoconvEndpoints: true,
logLevel: log.InfoLevel,
logLevel: logrus.InfoLevel,
}
}
// FromEnv fetches configuration
// from environment variables.
func FromEnv() (*Config, error) {
const op = "config.FromEnv"
c := defaultConfig()
defaultWaitTimeout, err := defaultWaitTimeoutFromEnv(defaultWaitTimeoutEnvVar, c.DefaultWaitTimeout())
c.defaultWaitTimeout = defaultWaitTimeout
if err != nil {
return c, err
return c, &standarderror.Error{Op: op, Err: err}
}
defaultListenPort, err := defaultListenPortFromEnv(defaultListenPortEnvVar, c.DefaultListenPort())
c.defaultListenPort = defaultListenPort
if err != nil {
return c, err
return c, &standarderror.Error{Op: op, Err: err}
}
disableChromeEndpoints, err := boolFromEnv(disableGoogleChromeEnvVar, c.EnableChromeEndpoints())
c.enableChromeEndpoints = !disableChromeEndpoints
if err != nil {
return c, err
return c, &standarderror.Error{Op: op, Err: err}
}
disableUnoconvEndpoints, err := boolFromEnv(disableUnoconvEnvVar, c.EnableUnoconvEndpoints())
c.enableUnoconvEndpoints = !disableUnoconvEndpoints
if err != nil {
return c, err
return c, &standarderror.Error{Op: op, Err: err}
}
logLevel, err := logLevelFromEnv(logLevelEnvVar, c.LogLevel())
c.logLevel = logLevel
if err != nil {
return c, err
return c, &standarderror.Error{Op: op, Err: err}
}
return c, nil
}
func (c *Config) DefaultWaitTimeout() float64 { return c.defaultWaitTimeout }
func (c *Config) DefaultListenPort() string { return c.defaultListenPort }
func (c *Config) EnableChromeEndpoints() bool { return c.enableChromeEndpoints }
func (c *Config) EnableUnoconvEndpoints() bool { return c.enableUnoconvEndpoints }
func (c *Config) LogLevel() log.Level { return c.logLevel }
// DefaultWaitTimeout returns the default
// wait timeout from the configuration.
func (c *Config) DefaultWaitTimeout() float64 {
return c.defaultWaitTimeout
}
// DefaultListenPort returns the default
// listen port from the configuration.
func (c *Config) DefaultListenPort() string {
return c.defaultListenPort
}
// EnableChromeEndpoints returns true if
// Chrome endpoints are enabled in the
// configuration.
func (c *Config) EnableChromeEndpoints() bool {
return c.enableChromeEndpoints
}
// EnableUnoconvEndpoints returns true if
// Unoconv endpoints are enabled in the
// configuration.
func (c *Config) EnableUnoconvEndpoints() bool {
return c.enableUnoconvEndpoints
}
// LogLevel returns the logrus.Level from
// the configuration.
func (c *Config) LogLevel() logrus.Level {
return c.logLevel
}
func defaultWaitTimeoutFromEnv(envVar string, defaultValue float64) (float64, error) {
const op = "defaultWaitTimeoutFromEnv"
if v, ok := os.LookupEnv(envVar); ok {
waitTimeout, err := strconv.ParseFloat(v, 64)
if err != nil {
return defaultValue, fmt.Errorf("%s: wrong value: want float got %v", envVar, err)
return defaultValue, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not a float, got '%s'", envVar, v),
Op: op,
}
}
return waitTimeout, nil
}
@@ -82,13 +119,22 @@ func defaultWaitTimeoutFromEnv(envVar string, defaultValue float64) (float64, er
}
func defaultListenPortFromEnv(envVar string, defaultValue string) (string, error) {
const op = "defaultListenPortFromEnv"
if v, ok := os.LookupEnv(envVar); ok {
portAsUint, err := strconv.ParseUint(v, 10, 64)
if err != nil {
return defaultValue, fmt.Errorf("%s: wrong value: want uint got %v", envVar, err)
return defaultValue, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not a uint, got '%s'", envVar, v),
Op: op,
}
}
if portAsUint > 65535 {
return defaultValue, fmt.Errorf("%s: wrong value: want uint < 65535 got %d", envVar, portAsUint)
return defaultValue, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not a uint < 65535, got '%d'", envVar, portAsUint),
Op: op,
}
}
return v, nil
}
@@ -96,26 +142,36 @@ func defaultListenPortFromEnv(envVar string, defaultValue string) (string, error
}
func boolFromEnv(envVar string, defaultValue bool) (bool, error) {
const op = "boolFromEnv"
if v, ok := os.LookupEnv(envVar); ok {
if v != "1" && v != "0" {
return defaultValue, fmt.Errorf("%s: wrong value: want \"0\" or \"1\" got %s", envVar, v)
return defaultValue, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not '0' or '1', got %s", envVar, v),
Op: op,
}
}
return v == "1", nil
}
return defaultValue, nil
}
func logLevelFromEnv(envVar string, defaultValue log.Level) (log.Level, error) {
func logLevelFromEnv(envVar string, defaultValue logrus.Level) (logrus.Level, error) {
const op = "logLevelFromEnv"
if v, ok := os.LookupEnv(envVar); ok {
switch v {
case "DEBUG":
return log.DebugLevel, nil
return logrus.DebugLevel, nil
case "INFO":
return log.InfoLevel, nil
return logrus.InfoLevel, nil
case "ERROR":
return log.ErrorLevel, nil
return logrus.ErrorLevel, nil
default:
return defaultValue, fmt.Errorf("%s: wrong value: want \"DEBUG\",\"INFO\" or \"ERROR\" got %s", envVar, v)
return defaultValue, &standarderror.Error{
Code: standarderror.Invalid,
Message: fmt.Sprintf("'%s' is not 'DEBUG', 'INFO' or 'ERROR', got '%s'", envVar, v),
Op: op,
}
}
}
return defaultValue, nil

View File

@@ -1 +1,3 @@
// Package config gathers all
// configuration data.
package config

View File

@@ -1 +1,3 @@
// Package logger defines a standard
// logger for the application.
package logger

View File

@@ -1,33 +1,63 @@
package logger
import (
"os"
"github.com/mattn/go-isatty"
"github.com/sirupsen/logrus"
)
// Logger enforces specific log message formats.
type Logger struct {
*logrus.Entry
entry *logrus.Entry
}
// New initializes the logger.
func New(level logrus.Level, trace string) *Logger {
l := logrus.New()
l.SetLevel(level)
// TODO no formatter if TTY.
l.SetFormatter(&logrus.JSONFormatter{})
if !isatty.IsTerminal(os.Stdout.Fd()) {
l.SetFormatter(&logrus.JSONFormatter{})
}
return &Logger{
l.WithField("trace", trace),
entry: l.WithField("trace", trace),
}
}
// WithFields creates a new logger with
// given fields.
func (l *Logger) WithFields(fields map[string]interface{}) *Logger {
return &Logger{
entry: l.entry.WithFields(fields),
}
}
// DebugfOp logs a debug message for given
// logical operation.
func (l *Logger) DebugfOp(op string, format string, args ...interface{}) {
l.WithField("op", op).Debugf(format, args...)
l.entry.WithField("op", op).Debugf(format, args...)
}
// ErrorOp logs an error message for given
// InfofOp logs an info message for given
// logical operation.
func (l *Logger) InfofOp(op string, format string, args ...interface{}) {
l.entry.WithField("op", op).Infof(format, args...)
}
// ErrorOp logs an error for given
// logical operation.
func (l *Logger) ErrorOp(op string, err error) {
l.WithField("op", op).Error(err.Error())
l.entry.WithField("op", op).Error(err.Error())
}
// ErrorfOp logs an error message for given
// logical operation.
func (l *Logger) ErrorfOp(op string, message string) {
l.entry.WithField("op", op).Error(message)
}
// FatalOp logs an error message for given
// logical operation.
func (l *Logger) FatalOp(op string, err error) {
l.entry.WithField("op", op).Error(err.Error())
}

View File

@@ -6,6 +6,7 @@ import (
"github.com/mafredri/cdp/devtool"
"github.com/thecodingmachine/gotenberg/internal/pkg/logger"
"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
)
const warmupTime = 10 * time.Second
@@ -27,11 +28,19 @@ func (p *chrome) Fullname() string {
}
func (p *chrome) Start() error {
return p.manager.start(p)
const op = "chrome.Start"
if err := p.manager.start(p); err != nil {
return &standarderror.Error{Op: op, Err: err}
}
return nil
}
func (p *chrome) Shutdown() error {
return p.manager.shutdown(p)
const op = "chrome.Shutdown"
if err := p.manager.shutdown(p); err != nil {
return &standarderror.Error{Op: op, Err: err}
}
return nil
}
func (p *chrome) args() []string {
@@ -58,24 +67,38 @@ func (p *chrome) name() string {
}
func (p *chrome) viable() bool {
const debugOp = "chrome.viable"
// check if Google Chrome is correctly running.
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
p.manager.logger.Debugf(
"%s: checking liveness via debug version endpoint http://localhost:9222/json/version",
p.Fullname(),
p.manager.logger.DebugfOp(
debugOp,
"checking liveness via debug version endpoint http://localhost:9222/json/version",
)
v, err := devtool.New("http://localhost:9222").Version(ctx)
if err != nil {
p.manager.logger.Debugf("%s: debug version endpoint returned error: %v", p.Fullname(), err)
p.manager.logger.DebugfOp(
debugOp,
"debug version endpoint returned error: %v",
err,
)
return false
}
p.manager.logger.Debugf("%s: debug version endpoint returned version info: %+v", p.Fullname(), *v)
p.manager.logger.DebugfOp(
debugOp,
"debug version endpoint returned version info: %+v",
*v,
)
return true
}
func (p *chrome) warmup() {
p.manager.logger.Debugf("%s: allowing %v to startup", p.Fullname(), warmupTime)
const debugOp = "chrome.warmup"
p.manager.logger.DebugfOp(
debugOp,
"allowing %v to startup",
warmupTime,
)
time.Sleep(warmupTime)
}

View File

@@ -8,6 +8,7 @@ import (
"strings"
"github.com/thecodingmachine/gotenberg/internal/pkg/logger"
"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
)
const (
@@ -34,8 +35,9 @@ type processManager struct {
}
func (m *processManager) start(p Process) error {
const op = "pm2.start"
if err := m.pm2(p, "start"); err != nil {
return err
return &standarderror.Error{Op: op, Err: err}
}
p.warmup()
if !p.viable() {
@@ -43,14 +45,17 @@ func (m *processManager) start(p Process) error {
for attempts < 5 && !p.viable() {
if err := m.pm2(p, "restart"); err != nil {
m.heuristicState = errorState
return err
return &standarderror.Error{Op: op, Err: err}
}
p.warmup()
attempts++
}
if !p.viable() {
m.heuristicState = errorState
return fmt.Errorf("failed to launch %s", p.Fullname())
return &standarderror.Error{
Op: op,
Message: fmt.Sprintf("failed to launch %s", p.Fullname()),
}
}
}
m.heuristicState = runningState
@@ -58,18 +63,20 @@ func (m *processManager) start(p Process) error {
}
func (m *processManager) shutdown(p Process) error {
const op = "pm2.shutdown"
if m.heuristicState != runningState {
return nil
}
if err := m.pm2(p, "stop"); err != nil {
m.heuristicState = errorState
return err
return &standarderror.Error{Op: op, Err: err}
}
m.heuristicState = stoppedState
return nil
}
func (m *processManager) pm2(p Process, cmdName string) error {
const op = "pm2.pm2"
cmdArgs := []string{
cmdName,
p.name(),
@@ -82,35 +89,36 @@ func (m *processManager) pm2(p Process, cmdName string) error {
"pm2",
cmdArgs...,
)
m.logger.Debugf("executing command: %v", strings.Join(cmd.Args, " "))
m.logger.DebugfOp(op, "executing command: %s", strings.Join(cmd.Args, " "))
processStdOut, err := cmd.StdoutPipe()
if err != nil {
return fmt.Errorf("failed getting stdout from %s: %s", p.Fullname(), err)
return &standarderror.Error{Op: op, Err: err}
}
processStdErr, err := cmd.StderrPipe()
if err != nil {
return fmt.Errorf("failed getting stderr from %s: %s", p.Fullname(), err)
return &standarderror.Error{Op: op, Err: err}
}
readFromPipe := func(outputType string, reader io.ReadCloser) {
readFromPipeOp := fmt.Sprintf("pm2.%s.%s", p.name(), outputType)
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())
m.logger.ErrorOp(readFromPipeOp, err)
}
break
}
if len(line) != 0 {
m.logger.Debugf("%s %s: %s", p.Fullname(), outputType, string(line))
m.logger.DebugfOp(readFromPipeOp, string(line))
}
}
}
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 &standarderror.Error{Op: op, Err: err}
}
return nil
}

View File

@@ -2,6 +2,7 @@ package pm2
import (
"github.com/thecodingmachine/gotenberg/internal/pkg/logger"
"github.com/thecodingmachine/gotenberg/internal/pkg/standarderror"
)
type unoconv struct {
@@ -21,11 +22,19 @@ func (p *unoconv) Fullname() string {
}
func (p *unoconv) Start() error {
return p.manager.start(p)
const op = "unoconv.Start"
if err := p.manager.start(p); err != nil {
return &standarderror.Error{Op: op, Err: err}
}
return nil
}
func (p *unoconv) Shutdown() error {
return p.manager.shutdown(p)
const op = "unoconv.Shutdown"
if err := p.manager.shutdown(p); err != nil {
return &standarderror.Error{Op: op, Err: err}
}
return nil
}
func (p *unoconv) args() []string {

View File

@@ -1,5 +1,7 @@
// Package standarderror helps standardizing
// the errors in the application.
//
// Credits: https://middlemost.com/failure-is-your-domain/
/*
Package standarderror helps standardizing
the errors in the application.
Credits: https://middlemost.com/failure-is-your-domain/
*/
package standarderror

View File

@@ -35,10 +35,6 @@ type Error struct {
// Error returns the string representation of the error message.
func (err *Error) Error() string {
var buf bytes.Buffer
// print the current operation in our stack, if any.
if err.Op != "" {
fmt.Fprintf(&buf, "%s: ", err.Op)
}
// if wrapping an error, print its Error() message.
// Otherwise print the error code & message.
if err.Err != nil {
@@ -83,3 +79,31 @@ func Message(err error) string {
}
return "An internal error has occurred. Please contact technical support."
}
// Op returns the logical operation of the error, if available.
// Otherwise returns an empty string.
// FIXME: "resource.ChromePrinterOptions: float64: : "
func Op(err error) string {
if err == nil {
return ""
}
e, ok := err.(*Error)
if !ok {
return ""
}
var buf bytes.Buffer
if e.Op != "" {
fmt.Fprintf(&buf, "%s: ", e.Op)
}
if e.Err != nil {
if wrappedOp := Op(e.Err); wrappedOp != "" {
fmt.Fprintf(&buf, "%s: ", wrappedOp)
}
}
return buf.String()
}
// Compile-time checks to ensure type implements desired interfaces.
var (
_ = error(new(Error))
)