From 9a5646ad6c63b99edcd5e080d0b36dc9599b303c Mon Sep 17 00:00:00 2001 From: Marius Date: Fri, 23 Sep 2016 21:21:38 +0200 Subject: [PATCH] Add proper, formatted logging --- cmd/tusd/cli/hooks.go | 10 +++++----- cmd/tusd/cli/log.go | 6 ++++++ log.go | 27 +++++++++++++++++++++++++++ unrouted_handler.go | 41 +++++++++++++++++++++++++++++------------ 4 files changed, 67 insertions(+), 17 deletions(-) create mode 100644 log.go diff --git a/cmd/tusd/cli/hooks.go b/cmd/tusd/cli/hooks.go index 10c7abb..e8ba5ff 100644 --- a/cmd/tusd/cli/hooks.go +++ b/cmd/tusd/cli/hooks.go @@ -53,7 +53,7 @@ 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()) } }() } @@ -61,9 +61,9 @@ func invokeHook(typ HookType, info tusd.FileInfo) { 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 { @@ -71,7 +71,7 @@ func invokeHookSync(typ HookType, info tusd.FileInfo, captureOutput bool) ([]byt } 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 } diff --git a/cmd/tusd/cli/log.go b/cmd/tusd/cli/log.go index 84917e8..5cbeb62 100644 --- a/cmd/tusd/cli/log.go +++ b/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...) +} diff --git a/log.go b/log.go new file mode 100644 index 0000000..ffef931 --- /dev/null +++ b/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)) +} diff --git a/unrouted_handler.go b/unrouted_handler.go index 0876e5f..514060c 100644 --- a/unrouted_handler.go +++ b/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) +}