Add proper, formatted logging

cmd/tusd/cli/hooks.go

@@ -53,25 +53,25 @@ func invokeHook(typ HookType, info tusd.FileInfo) {
 	go func() {
 		_, err := invokeHookSync(typ, info, false)
 		if err != nil {
-			stderr.Printf("Error running %s hook for %s: %s", string(typ), info.ID, err)
+			logEv("HookInvocationError", "type", string(typ), "id", info.ID, "error", err.Error())
 		}
 	}()
 }
 
 func invokeHookSync(typ HookType, info tusd.FileInfo, captureOutput bool) ([]byte, error) {
 	switch typ {
 	case HookPostFinish:
-		stdout.Printf("Upload %s (%d bytes) finished\n", info.ID, info.Size)
+		logEv("UploadFinished", "id", info.ID, "size", strconv.FormatInt(info.Size, 10))
 	case HookPostTerminate:
-		stdout.Printf("Upload %s terminated\n", info.ID)
+		logEv("UploadTerminated", "id", info.ID)
 	}
 
 	if !Flags.HooksInstalled {
 		return nil, nil
 	}
 
 	name := string(typ)
-	stdout.Printf("Invoking %s hook…\n", name)
+	logEv("HookInvocationStart", "type", name, "id", info.ID)
 
 	cmd := exec.Command(Flags.HooksDir + "/" + name)
 	env := os.Environ()
@@ -103,7 +103,7 @@ func invokeHookSync(typ HookType, info tusd.FileInfo, captureOutput bool) ([]byt
 	// Ignore the error, only, if the hook's file could not be found. This usually
 	// means that the user is only using a subset of the available hooks.
 	if os.IsNotExist(err) {
-		stdout.Printf("Unable to invoke %s hook: %s\n", name, err)
+		logEv("HookInvocationError", "type", string(typ), "id", info.ID, "error", err.Error())
 		err = nil
 	}
 

cmd/tusd/cli/log.go

@@ -3,7 +3,13 @@ package cli
 import (
 	"log"
 	"os"
+
+	"github.com/tus/tusd"
 )
 
 var stdout = log.New(os.Stdout, "[tusd] ", 0)
 var stderr = log.New(os.Stderr, "[tusd] ", 0)
+
+func logEv(eventName string, details ...string) {
+	tusd.LogEvent(stderr, eventName, details...)
+}

log.go

@@ -0,0 +1,27 @@
+package tusd
+
+import (
+	"log"
+)
+
+func (h *UnroutedHandler) log(eventName string, details ...string) {
+	LogEvent(h.logger, eventName, details...)
+}
+
+func LogEvent(logger *log.Logger, eventName string, details ...string) {
+	result := make([]byte, 0, 100)
+
+	result = append(result, `event="`...)
+	result = append(result, eventName...)
+	result = append(result, `" `...)
+
+	for i := 0; i < len(details); i += 2 {
+		result = append(result, details[i]...)
+		result = append(result, `="`...)
+		result = append(result, details[i+1]...)
+		result = append(result, `" `...)
+	}
+
+	result = append(result, "\n"...)
+	logger.Output(2, string(result))
+}

unrouted_handler.go

@@ -126,10 +126,9 @@ func (handler *UnroutedHandler) Middleware(h http.Handler) http.Handler {
 			r.Method = newMethod
 		}
 
-		go func() {
-			handler.logger.Println(r.Method, r.URL.Path)
-			handler.Metrics.incRequestsTotal(r.Method)
-		}()
+		handler.log("RequestIncoming", "method", r.Method, "path", r.URL.Path)
+
+		go handler.Metrics.incRequestsTotal(r.Method)
 
 		header := w.Header()
 
@@ -171,7 +170,7 @@ func (handler *UnroutedHandler) Middleware(h http.Handler) http.Handler {
 			// will be ignored or interpreted as a rejection.
 			// For example, the Presto engine, which is used in older versions of
 			// Opera, Opera Mobile and Opera Mini, handles CORS this way.
-			w.WriteHeader(http.StatusOK)
+			handler.sendResp(w, r, http.StatusOK)
 			return
 		}
 
@@ -268,6 +267,7 @@ func (handler *UnroutedHandler) PostFile(w http.ResponseWriter, r *http.Request)
 	w.Header().Set("Location", url)
 
 	go handler.Metrics.incUploadsCreated()
+	handler.log("UploadCreated", "id", id, "size", i64toa(size), "url", url)
 
 	if isFinal {
 		if err := handler.composer.Concater.ConcatUploads(id, partialUploads); err != nil {
@@ -299,7 +299,7 @@ func (handler *UnroutedHandler) PostFile(w http.ResponseWriter, r *http.Request)
 		}
 	}
 
-	w.WriteHeader(http.StatusCreated)
+	handler.sendResp(w, r, http.StatusCreated)
 }
 
 // HeadFile returns the length and offset for the HEAD request
@@ -347,7 +347,7 @@ func (handler *UnroutedHandler) HeadFile(w http.ResponseWriter, r *http.Request)
 	w.Header().Set("Cache-Control", "no-store")
 	w.Header().Set("Upload-Length", strconv.FormatInt(info.Size, 10))
 	w.Header().Set("Upload-Offset", strconv.FormatInt(info.Offset, 10))
-	w.WriteHeader(http.StatusOK)
+	handler.sendResp(w, r, http.StatusOK)
 }
 
 // PatchFile adds a chunk to an upload. Only allowed enough space is left.
@@ -402,7 +402,7 @@ func (handler *UnroutedHandler) PatchFile(w http.ResponseWriter, r *http.Request
 	// Do not proxy the call to the data store if the upload is already completed
 	if info.Offset == info.Size {
 		w.Header().Set("Upload-Offset", strconv.FormatInt(offset, 10))
-		w.WriteHeader(http.StatusNoContent)
+		handler.sendResp(w, r, http.StatusNoContent)
 		return
 	}
 
@@ -411,7 +411,7 @@ func (handler *UnroutedHandler) PatchFile(w http.ResponseWriter, r *http.Request
 		return
 	}
 
-	w.WriteHeader(http.StatusNoContent)
+	handler.sendResp(w, r, http.StatusNoContent)
 }
 
 // PatchFile adds a chunk to an upload. Only allowed enough space is left.
@@ -430,6 +430,8 @@ func (handler *UnroutedHandler) writeChunk(id string, info FileInfo, w http.Resp
 		maxSize = length
 	}
 
+	handler.log("ChunkWriteStart", "id", id, "maxSize", i64toa(maxSize), "offset", i64toa(offset))
+
 	var bytesWritten int64
 	// Prevent a nil pointer derefernce when accessing the body which may not be
 	// available in the case of a malicious request.
@@ -444,6 +446,8 @@ func (handler *UnroutedHandler) writeChunk(id string, info FileInfo, w http.Resp
 		}
 	}
 
+	handler.log("ChunkWriteComplete", "id", id, "bytesWritten", i64toa(bytesWritten))
+
 	// Send new offset to client
 	newOffset := offset + bytesWritten
 	w.Header().Set("Upload-Offset", strconv.FormatInt(newOffset, 10))
@@ -502,7 +506,7 @@ func (handler *UnroutedHandler) GetFile(w http.ResponseWriter, r *http.Request)
 
 	// Do not do anything if no data is stored yet.
 	if info.Offset == 0 {
-		w.WriteHeader(http.StatusNoContent)
+		handler.sendResp(w, r, http.StatusNoContent)
 		return
 	}
 
@@ -518,7 +522,7 @@ func (handler *UnroutedHandler) GetFile(w http.ResponseWriter, r *http.Request)
 	}
 
 	w.Header().Set("Content-Length", strconv.FormatInt(info.Offset, 10))
-	w.WriteHeader(http.StatusOK)
+	handler.sendResp(w, r, http.StatusOK)
 	io.Copy(w, src)
 
 	// Try to close the reader if the io.Closer interface is implemented
@@ -566,7 +570,7 @@ func (handler *UnroutedHandler) DelFile(w http.ResponseWriter, r *http.Request)
 		return
 	}
 
-	w.WriteHeader(http.StatusNoContent)
+	handler.sendResp(w, r, http.StatusNoContent)
 
 	if handler.config.NotifyTerminatedUploads {
 		handler.TerminatedUploads <- info
@@ -598,9 +602,18 @@ func (handler *UnroutedHandler) sendError(w http.ResponseWriter, r *http.Request
 	w.WriteHeader(status)
 	w.Write([]byte(reason))
 
+	handler.log("ResponseOutgoing", "status", strconv.Itoa(status), "method", r.Method, "path", r.URL.Path, "error", err.Error())
+
 	go handler.Metrics.incErrorsTotal(err)
 }
 
+// sendResp writes the header to w with the specified status code.
+func (handler *UnroutedHandler) sendResp(w http.ResponseWriter, r *http.Request, status int) {
+	w.WriteHeader(status)
+
+	handler.log("ResponseOutgoing", "status", strconv.Itoa(status), "method", r.Method, "path", r.URL.Path)
+}
+
 // Make an absolute URLs to the given upload id. If the base path is absolute
 // it will be prepended else the host and protocol from the request is used.
 func (handler *UnroutedHandler) absFileURL(r *http.Request, id string) string {
@@ -772,3 +785,7 @@ func extractIDFromPath(url string) (string, error) {
 	}
 	return result[1], nil
 }
+
+func i64toa(num int64) string {
+	return strconv.FormatInt(num, 10)
+}