improving logging (#5)

* small refactoring of error messages

* (very) small refactoring of structs instantiation

* improving logging with debug messages

* using INFO level as default + changing previous debug message to info message

app/config/config_test.go

@@ -119,9 +119,9 @@ func TestFileExtensionAlreadyUsedError(t *testing.T) {
 	ext := ".pdf"
 	cmd1, _ := NewCommand("echo", 0)
 	cmd2, _ := NewCommand("echo", 0)
-	expected := fmt.Sprintf(fileExtensionAlreadyUsedErrorMessage, ext, cmd1.Template.Name(), cmd2.Template.Name())
-
 	err := &fileExtensionAlreadyUsedError{ext, cmd1, cmd2}
+	expected := fmt.Sprintf(fileExtensionAlreadyUsedErrorMessage, err.extension, err.command.Template.Name(), err.existingCommand.Template.Name())
+
 	if err.Error() != expected {
 		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), expected)
 	}
@@ -143,10 +143,9 @@ func TestWithCommand(t *testing.T) {
 }
 
 func TestNoCommandFoundForFileExtensionError(t *testing.T) {
-	ext := ".pdf"
-	expected := fmt.Sprintf(noCommandFoundForFileExtensionErrorMessage, ext)
+	err := &noCommandFoundForFileExtensionError{".pdf"}
+	expected := fmt.Sprintf(noCommandFoundForFileExtensionErrorMessage, err.extension)
 
-	err := &noCommandFoundForFileExtensionError{ext}
 	if err.Error() != expected {
 		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), expected)
 	}

app/context/context.go

@@ -28,7 +28,7 @@ func WithConverter(r *http.Request, converter *converter.Converter) *http.Reques
 
 type converterNotFoundError struct{}
 
-const converterNotFoundErrorMessage = "The converter was not found in request context"
+const converterNotFoundErrorMessage = "the converter was not found in request context"
 
 func (e *converterNotFoundError) Error() string {
 	return converterNotFoundErrorMessage
@@ -57,7 +57,7 @@ func WithResultFilePath(r *http.Request, resultFilePath string) *http.Request {
 
 type resultFilePathNotFoundError struct{}
 
-const resultFilePathNotFoundErrorMessage = "The result file path was not found in request context"
+const resultFilePathNotFoundErrorMessage = "the result file path was not found in request context"
 
 func (e *resultFilePathNotFoundError) Error() string {
 	return resultFilePathNotFoundErrorMessage

app/converter/converter.go

@@ -9,6 +9,7 @@ import (
 
 	gfile "github.com/thecodingmachine/gotenberg/app/converter/file"
 	"github.com/thecodingmachine/gotenberg/app/converter/process"
+	"github.com/thecodingmachine/gotenberg/app/logger"
 
 	"github.com/satori/go.uuid"
 )
@@ -22,7 +23,7 @@ type Converter struct {
 // NoFileToConvertError is raided when a request has not file attached to it.
 type NoFileToConvertError struct{}
 
-const noFileToConvertErrorMessage = "No file to convert"
+const noFileToConvertErrorMessage = "no file to convert"
 
 func (e *NoFileToConvertError) Error() string {
 	return noFileToConvertErrorMessage
@@ -38,6 +39,8 @@ func NewConverter(r *http.Request) (*Converter, error) {
 		return nil, err
 	}
 
+	logger.Debugf("created working directory %s", c.workingDir)
+
 	reader, err := r.MultipartReader()
 	if err != nil {
 		return c, err
@@ -101,5 +104,11 @@ func (c *Converter) Convert() (string, error) {
 
 // Clear removes all file inside its working directory.
 func (c *Converter) Clear() error {
-	return os.RemoveAll(c.workingDir)
+	if err := os.RemoveAll(c.workingDir); err != nil {
+		logger.Error(fmt.Errorf("failed to remove working directory %s", c.workingDir))
+		return err
+	}
+
+	logger.Debugf("removed working directory %s", c.workingDir)
+	return nil
 }

app/converter/converter_test.go

@@ -48,6 +48,13 @@ func load(configurationFilePath string) {
 	config.ParseFile(path)
 }
 
+func TestNoFileToConvertError(t *testing.T) {
+	err := &NoFileToConvertError{}
+	if err.Error() != noFileToConvertErrorMessage {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), noFileToConvertErrorMessage)
+	}
+}
+
 func TestNewConverter(t *testing.T) {
 	var (
 		path  string
@@ -141,10 +148,3 @@ func TestClear(t *testing.T) {
 		t.Error("Converter should have been able to clear itself")
 	}
 }
-
-func TestNoFileToConvertError(t *testing.T) {
-	err := &NoFileToConvertError{}
-	if err.Error() != noFileToConvertErrorMessage {
-		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), noFileToConvertErrorMessage)
-	}
-}

app/converter/file/file.go

@@ -8,7 +8,9 @@ import (
 	"path/filepath"
 
 	"github.com/thecodingmachine/gotenberg/app/config"
+	"github.com/thecodingmachine/gotenberg/app/logger"
 
+	"github.com/dustin/go-humanize"
 	"github.com/satori/go.uuid"
 )
 
@@ -30,10 +32,7 @@ func NewFile(workingDir string, r io.Reader, fileName string) (*File, error) {
 		return nil, err
 	}
 
-	f := &File{
-		Extension: ext,
-		Path:      MakeFilePath(workingDir, ext),
-	}
+	f := &File{ext, MakeFilePath(workingDir, ext)}
 
 	file, err := os.Create(f.Path)
 	if err != nil {
@@ -42,7 +41,7 @@ func NewFile(workingDir string, r io.Reader, fileName string) (*File, error) {
 
 	defer file.Close()
 
-	_, err = io.Copy(file, r)
+	n, err := io.Copy(file, r)
 	if err != nil {
 		return nil, err
 	}
@@ -50,6 +49,7 @@ func NewFile(workingDir string, r io.Reader, fileName string) (*File, error) {
 	// resets the read pointer.
 	file.Seek(0, 0)
 
+	logger.Debugf("working file %s has been created from %s (%s copied)", f.Path, fileName, humanize.Bytes(uint64(n)))
 	return f, nil
 }
 

app/converter/process/process.go

@@ -10,6 +10,7 @@ import (
 
 	"github.com/thecodingmachine/gotenberg/app/config"
 	gfile "github.com/thecodingmachine/gotenberg/app/converter/file"
+	"github.com/thecodingmachine/gotenberg/app/logger"
 )
 
 type runner struct {
@@ -23,8 +24,10 @@ type commandTimeoutError struct {
 	timeout int
 }
 
+const commandTimeoutErrorMessage = "the command '%s' has reached the %d second(s) timeout"
+
 func (e *commandTimeoutError) Error() string {
-	return fmt.Sprintf("The command '%s' has reached the %d second(s) timeout", e.command, e.timeout)
+	return fmt.Sprintf(commandTimeoutErrorMessage, e.command, e.timeout)
 }
 
 // run runs the given command. If timeout is reached or
@@ -34,6 +37,8 @@ func (r *runner) run(command string, timeout int) error {
 	defer r.mu.Unlock()
 
 	cmd := exec.Command("/bin/sh", "-c", command)
+	logger.Debugf("executing command %s", cmd.Args)
+
 	if err := cmd.Start(); err != nil {
 		return err
 	}
@@ -49,10 +54,8 @@ func (r *runner) run(command string, timeout int) error {
 		if err := cmd.Process.Kill(); err != nil {
 			return err
 		}
-		return &commandTimeoutError{
-			command: command,
-			timeout: timeout,
-		}
+
+		return &commandTimeoutError{command, timeout}
 	case err := <-done:
 		if err != nil {
 			return err
@@ -70,10 +73,7 @@ type conversionData struct {
 
 // Unconv converts a file to PDF and returns the new file path.
 func Unconv(workingDir string, file *gfile.File) (string, error) {
-	cmdData := &conversionData{
-		FilePath:       file.Path,
-		ResultFilePath: gfile.MakeFilePath(workingDir, ".pdf"),
-	}
+	cmdData := &conversionData{file.Path, gfile.MakeFilePath(workingDir, ".pdf")}
 
 	cmd, err := config.GetCommand(file.Extension)
 	if err != nil {
@@ -90,6 +90,7 @@ func Unconv(workingDir string, file *gfile.File) (string, error) {
 		return "", err
 	}
 
+	logger.Debugf("created %s from %s", cmdData.ResultFilePath, cmdData.FilePath)
 	return cmdData.ResultFilePath, nil
 }
 
@@ -101,10 +102,7 @@ type mergeData struct {
 
 // Merge merges many PDF files to one unique PDF file and returns the new file path.
 func Merge(workingDir string, filesPaths []string) (string, error) {
-	cmdData := &mergeData{
-		FilesPaths:     filesPaths,
-		ResultFilePath: gfile.MakeFilePath(workingDir, ".pdf"),
-	}
+	cmdData := &mergeData{filesPaths, gfile.MakeFilePath(workingDir, ".pdf")}
 
 	cmd, err := config.GetCommand(".pdf")
 	if err != nil {
@@ -121,5 +119,6 @@ func Merge(workingDir string, filesPaths []string) (string, error) {
 		return "", err
 	}
 
+	logger.Debugf("created %s from %+v", cmdData.ResultFilePath, cmdData.FilesPaths)
 	return cmdData.ResultFilePath, nil
 }

app/converter/process/process_test.go

@@ -28,6 +28,15 @@ func load(configurationFilePath string) {
 	config.ParseFile(path)
 }
 
+func TestCommandTimeoutError(t *testing.T) {
+	err := &commandTimeoutError{"echo hello", 30}
+	expected := fmt.Sprintf(commandTimeoutErrorMessage, err.command, err.timeout)
+
+	if err.Error() != expected {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), expected)
+	}
+}
+
 func TestRun(t *testing.T) {
 	var cmd string
 
@@ -118,14 +127,3 @@ func TestMerge(t *testing.T) {
 
 	os.RemoveAll(workingDir)
 }
-
-func TestCommandTimeoutError(t *testing.T) {
-	err := &commandTimeoutError{
-		command: "echo hello",
-		timeout: 30,
-	}
-	expected := fmt.Sprintf("The command '%s' has reached the %d second(s) timeout", err.command, err.timeout)
-	if err.Error() != expected {
-		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), expected)
-	}
-}

app/handlers.go

@@ -12,6 +12,7 @@ import (
 	ghttp "github.com/thecodingmachine/gotenberg/app/http"
 	"github.com/thecodingmachine/gotenberg/app/logger"
 
+	"github.com/dustin/go-humanize"
 	"github.com/justinas/alice"
 )
 
@@ -23,8 +24,10 @@ func GetHandlersChain() http.Handler {
 
 type requestHasNoContentError struct{}
 
+const requestHasNoContentErrorMessage = "request has not content"
+
 func (e *requestHasNoContentError) Error() string {
-	return "Request has not content"
+	return requestHasNoContentErrorMessage
 }
 
 // enforeContentLengthHandler checks if the request has content.
@@ -120,6 +123,8 @@ func serveHandler(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	logger.Debugf("serving result file %s...", path)
+
 	done := make(chan error, 1)
 	go func() {
 		w.Header().Set("Content-Disposition", fmt.Sprintf("attachment; filename=\"%s\"", resultFileInfo.Name()))
@@ -136,6 +141,7 @@ func serveHandler(w http.ResponseWriter, r *http.Request) {
 		logger.Error(err)
 	}
 
+	logger.Infof("result file %s (%s) sent", path, humanize.Bytes(uint64(resultFileInfo.Size())))
 	cleanup(r)
 }
 
@@ -143,11 +149,11 @@ func serveHandler(w http.ResponseWriter, r *http.Request) {
 func cleanup(r *http.Request) {
 	c, err := context.GetConverter(r)
 	if err != nil {
-		logger.Warn(err.Error())
+		logger.Error(err)
 		return
 	}
 
 	if err := c.Clear(); err != nil {
-		logger.Warn(err.Error())
+		logger.Error(err)
 	}
 }

app/handlers_test.go

@@ -62,6 +62,13 @@ func TestGetHandlersChain(t *testing.T) {
 	}
 }
 
+func TestRequestHasNoContentError(t *testing.T) {
+	err := &requestHasNoContentError{}
+	if err.Error() != requestHasNoContentErrorMessage {
+		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), requestHasNoContentErrorMessage)
+	}
+}
+
 func TestEnforceContentLengthHandler(t *testing.T) {
 	var (
 		req *http.Request

app/http/http.go

@@ -15,8 +15,10 @@ const MultipartFormDataContentType ContentType = "multipart/form-data"
 
 type notAuthorizedContentTypeError struct{}
 
+const notAuthorizedContentTypeErrorMessage = "accepted value for 'Content-Type': %s"
+
 func (e *notAuthorizedContentTypeError) Error() string {
-	return fmt.Sprintf("Accepted value for 'Content-Type': %s", MultipartFormDataContentType)
+	return fmt.Sprintf(notAuthorizedContentTypeErrorMessage, MultipartFormDataContentType)
 }
 
 // CheckAuthorizedContentType checks if the request header header has an authorized content type.

app/http/http_test.go

@@ -31,7 +31,8 @@ func TestCheckAuthorizedContentType(t *testing.T) {
 
 func TestNotAuthorizedContentTypeError(t *testing.T) {
 	err := &notAuthorizedContentTypeError{}
-	expected := fmt.Sprintf("Accepted value for 'Content-Type': %s", MultipartFormDataContentType)
+	expected := fmt.Sprintf(notAuthorizedContentTypeErrorMessage, MultipartFormDataContentType)
+
 	if err.Error() != expected {
 		t.Errorf("Error returned a wrong message: got '%s' want '%s'", err.Error(), expected)
 	}

app/logger/logger.go

@@ -17,10 +17,7 @@ var log = newLogger()
 
 // newLogger instantiates a logger instance with default values.
 func newLogger() *logger {
-	l := &logger{
-		logger: logrus.New(),
-	}
-
+	l := &logger{logrus.New()}
 	l.logger.Out = os.Stdout
 	l.logger.Level = logrus.InfoLevel
 
@@ -45,7 +42,7 @@ func Debug(message string) {
 
 // Debugf is a wrapper of the logrus Debugf function.
 func Debugf(format string, args ...interface{}) {
-	log.logger.Debugf(format, args)
+	log.logger.Debugf(format, args...)
 }
 
 // Info is a wrapper of the logrus Info function.
@@ -55,7 +52,7 @@ func Info(message string) {
 
 // Infof is a wrapper of the logrus Infof function.
 func Infof(format string, args ...interface{}) {
-	log.logger.Infof(format, args)
+	log.logger.Infof(format, args...)
 }
 
 // Warn is a wrapper of the logrus Warn function.
@@ -63,6 +60,11 @@ func Warn(message string) {
 	log.logger.Warn(message)
 }
 
+// Warnf is wrapper of the logrus Warnf function.
+func Warnf(format string, args ...interface{}) {
+	log.logger.Warnf(format, args...)
+}
+
 // Error is a wrapper of the logrus Error function.
 func Error(err error) {
 	log.logger.Error(err.Error())