From 1242fdba22789ea276a3ccc8fd01a6cc6697f466 Mon Sep 17 00:00:00 2001 From: Robert Swain Date: Fri, 19 May 2017 12:21:10 +0200 Subject: [PATCH] mediaapi: Improve logging throughout, leveraging logrus features --- .../cmd/dendrite-media-api-server/main.go | 15 ++-- .../dendrite/mediaapi/writers/download.go | 70 ++++++++++++------- .../dendrite/mediaapi/writers/fileutils.go | 4 +- .../dendrite/mediaapi/writers/upload.go | 17 +++-- 4 files changed, 68 insertions(+), 38 deletions(-) diff --git a/src/github.com/matrix-org/dendrite/cmd/dendrite-media-api-server/main.go b/src/github.com/matrix-org/dendrite/cmd/dendrite-media-api-server/main.go index 1d827eba2..d7191508a 100644 --- a/src/github.com/matrix-org/dendrite/cmd/dendrite-media-api-server/main.go +++ b/src/github.com/matrix-org/dendrite/cmd/dendrite-media-api-server/main.go @@ -50,7 +50,7 @@ func main() { } absBasePath, err := filepath.Abs(basePath) if err != nil { - log.Panicf("BASE_PATH is invalid (must be able to make absolute): %v\n", err) + log.WithError(err).WithField("BASE_PATH", basePath).Panic("BASE_PATH is invalid (must be able to make absolute)") } if serverName == "" { @@ -59,7 +59,7 @@ func main() { maxFileSizeBytes, err := strconv.ParseInt(maxFileSizeBytesString, 10, 64) if err != nil { maxFileSizeBytes = 10 * 1024 * 1024 - log.Infof("Failed to parse MAX_FILE_SIZE_BYTES. Defaulting to %v bytes.", maxFileSizeBytes) + log.WithError(err).WithField("MAX_FILE_SIZE_BYTES", maxFileSizeBytesString).Warnf("Failed to parse MAX_FILE_SIZE_BYTES. Defaulting to %v bytes.", maxFileSizeBytes) } cfg := &config.MediaAPI{ @@ -71,10 +71,17 @@ func main() { db, err := storage.Open(cfg.DataSource) if err != nil { - log.Panicln("Failed to open database:", err) + log.WithError(err).Panic("Failed to open database") } - log.Info("Starting mediaapi") + log.WithFields(log.Fields{ + "BASE_PATH": absBasePath, + "BIND_ADDRESS": bindAddr, + "DATABASE": dataSource, + "LOG_DIR": logDir, + "MAX_FILE_SIZE_BYTES": maxFileSizeBytes, + "SERVER_NAME": serverName, + }).Info("Starting mediaapi") routing.Setup(http.DefaultServeMux, http.DefaultClient, cfg, db) log.Fatal(http.ListenAndServe(bindAddr, nil)) diff --git a/src/github.com/matrix-org/dendrite/mediaapi/writers/download.go b/src/github.com/matrix-org/dendrite/mediaapi/writers/download.go index fb2e5c95b..54bb3d5b1 100644 --- a/src/github.com/matrix-org/dendrite/mediaapi/writers/download.go +++ b/src/github.com/matrix-org/dendrite/mediaapi/writers/download.go @@ -145,7 +145,7 @@ func Download(w http.ResponseWriter, req *http.Request, origin gomatrixserverlib r.Logger.WithFields(log.Fields{ "MediaID": r.MediaMetadata.MediaID, "Origin": r.MediaMetadata.Origin, - }).Warnf("Other goroutines are trying to download the remote file and failing.") + }).Warn("Other goroutines are trying to download the remote file and failing.") r.jsonErrorResponse(w, util.JSONResponse{ Code: 500, JSON: jsonerror.Unknown(fmt.Sprintf("File with media ID %q could not be downloaded from %q", r.MediaMetadata.MediaID, r.MediaMetadata.Origin)), @@ -156,7 +156,7 @@ func Download(w http.ResponseWriter, req *http.Request, origin gomatrixserverlib r.Logger.WithFields(log.Fields{ "Origin": r.MediaMetadata.Origin, "MediaID": r.MediaMetadata.MediaID, - }).Infof("Waiting for another goroutine to fetch the remote file.") + }).Info("Waiting for another goroutine to fetch the remote file.") activeRemoteRequestCondition.Wait() activeRemoteRequests.Unlock() } else { @@ -169,7 +169,7 @@ func Download(w http.ResponseWriter, req *http.Request, origin gomatrixserverlib r.respondFromRemoteFile(w, cfg.AbsBasePath, cfg.MaxFileSizeBytes, db, activeRemoteRequests) } else { // If we do not have a record and the origin is local, or if we have another error from the database, the file is not found - r.Logger.Warnln("Failed to look up file in database:", err) + r.Logger.WithError(err).Warn("Failed to look up file in database") r.jsonErrorResponse(w, util.JSONResponse{ Code: 404, JSON: jsonerror.NotFound(fmt.Sprintf("File with media ID %q does not exist", r.MediaMetadata.MediaID)), @@ -190,7 +190,7 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat filePath, err := getPathFromMediaMetadata(r.MediaMetadata, absBasePath) if err != nil { // FIXME: Remove erroneous file from database? - r.Logger.Warnln("Failed to get file path from metadata:", err) + r.Logger.WithError(err).Warn("Failed to get file path from metadata") r.jsonErrorResponse(w, util.JSONResponse{ Code: 404, JSON: jsonerror.NotFound(fmt.Sprintf("File with media ID %q does not exist", r.MediaMetadata.MediaID)), @@ -200,7 +200,7 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat file, err := os.Open(filePath) if err != nil { // FIXME: Remove erroneous file from database? - r.Logger.Warnln("Failed to open file:", err) + r.Logger.WithError(err).Warn("Failed to open file") r.jsonErrorResponse(w, util.JSONResponse{ Code: 404, JSON: jsonerror.NotFound(fmt.Sprintf("File with media ID %q does not exist", r.MediaMetadata.MediaID)), @@ -211,7 +211,7 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat stat, err := file.Stat() if err != nil { // FIXME: Remove erroneous file from database? - r.Logger.Warnln("Failed to stat file:", err) + r.Logger.WithError(err).Warn("Failed to stat file") r.jsonErrorResponse(w, util.JSONResponse{ Code: 404, JSON: jsonerror.NotFound(fmt.Sprintf("File with media ID %q does not exist", r.MediaMetadata.MediaID)), @@ -220,7 +220,10 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat } if r.MediaMetadata.ContentLength > 0 && int64(r.MediaMetadata.ContentLength) != stat.Size() { - r.Logger.Warnf("File size in database (%v) and on disk (%v) differ.", r.MediaMetadata.ContentLength, stat.Size()) + r.Logger.WithFields(log.Fields{ + "contentLength": r.MediaMetadata.ContentLength, + "fileSize": stat.Size(), + }).Warn("Content-Length in database and on-disk file size differ.") // FIXME: Remove erroneous file from database? } @@ -234,7 +237,7 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat w.Header().Set("Content-Security-Policy", contentSecurityPolicy) if bytesResponded, err := io.Copy(w, file); err != nil { - r.Logger.Warnf("Failed to copy from cache %v\n", err) + r.Logger.WithError(err).Warn("Failed to copy from cache") if bytesResponded == 0 { r.jsonErrorResponse(w, util.JSONResponse{ Code: 500, @@ -249,7 +252,7 @@ func (r *downloadRequest) respondFromLocalFile(w http.ResponseWriter, absBasePat func (r *downloadRequest) createRemoteRequest() (*http.Response, *util.JSONResponse) { urls := getMatrixUrls(r.MediaMetadata.Origin) - r.Logger.Printf("Connecting to remote %q\n", urls[0]) + r.Logger.WithField("URL", urls[0]).Info("Connecting to remote") remoteReqAddr := urls[0] + "/_matrix/media/v1/download/" + string(r.MediaMetadata.Origin) + "/" + string(r.MediaMetadata.MediaID) remoteReq, err := http.NewRequest("GET", remoteReqAddr, nil) @@ -272,9 +275,17 @@ func (r *downloadRequest) createRemoteRequest() (*http.Response, *util.JSONRespo } if resp.StatusCode != 200 { - r.Logger.Printf("Server responded with %d\n", resp.StatusCode) + r.Logger.WithFields(log.Fields{ + "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, + "StatusCode": resp.StatusCode, + }).Info("Received error response") if resp.StatusCode == 404 { - r.Logger.Warnln("Remote server says file does not exist") + r.Logger.WithFields(log.Fields{ + "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, + "StatusCode": resp.StatusCode, + }).Warn("Remote server says file does not exist") return nil, &util.JSONResponse{ Code: 404, JSON: jsonerror.NotFound(fmt.Sprintf("File with media ID %q does not exist", r.MediaMetadata.MediaID)), @@ -339,15 +350,24 @@ func copyToActiveAndPassive(r io.Reader, wActive io.Writer, wPassive io.Writer, } func (r *downloadRequest) closeConnection(w http.ResponseWriter) { - r.Logger.Println("Attempting to close the connection.") + r.Logger.WithFields(log.Fields{ + "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, + }).Info("Attempting to close the connection.") hijacker, ok := w.(http.Hijacker) if ok { connection, _, hijackErr := hijacker.Hijack() if hijackErr == nil { - r.Logger.Println("Closing") + r.Logger.WithFields(log.Fields{ + "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, + }).Info("Closing") connection.Close() } else { - r.Logger.Printf("Error trying to hijack: %v", hijackErr) + r.Logger.WithError(hijackErr).WithFields(log.Fields{ + "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, + }).Warn("Error trying to hijack and close connection") } } } @@ -370,15 +390,15 @@ func (r *downloadRequest) commitFileAndMetadata(tmpDir types.Path, absBasePath t "Content-Length": r.MediaMetadata.ContentLength, "Content-Type": r.MediaMetadata.ContentType, "Content-Disposition": r.MediaMetadata.ContentDisposition, - }).Infof("Storing file metadata to media repository database") + }).Info("Storing file metadata to media repository database") // The database is the source of truth so we need to have moved the file first finalPath, err := getPathFromMediaMetadata(r.MediaMetadata, absBasePath) if err != nil { - r.Logger.Warnf("Failed to get file path from metadata: %q\n", err) + r.Logger.WithError(err).Warn("Failed to get file path from metadata") tmpDirErr := os.RemoveAll(string(tmpDir)) if tmpDirErr != nil { - r.Logger.Warnf("Failed to remove tmpDir (%v): %q\n", tmpDir, tmpDirErr) + r.Logger.WithError(tmpDirErr).WithField("dir", tmpDir).Warn("Failed to remove tmpDir") } return updateActiveRemoteRequests } @@ -388,10 +408,10 @@ func (r *downloadRequest) commitFileAndMetadata(tmpDir types.Path, absBasePath t types.Path(finalPath), ) if err != nil { - r.Logger.Warnf("Failed to move file to final destination: %q\n", err) + r.Logger.WithError(err).WithField("dst", finalPath).Warn("Failed to move file to final destination") tmpDirErr := os.RemoveAll(string(tmpDir)) if tmpDirErr != nil { - r.Logger.Warnf("Failed to remove tmpDir (%v): %q\n", tmpDir, tmpDirErr) + r.Logger.WithError(tmpDirErr).WithField("dir", tmpDir).Warn("Failed to remove tmpDir") } return updateActiveRemoteRequests } @@ -410,7 +430,7 @@ func (r *downloadRequest) commitFileAndMetadata(tmpDir types.Path, absBasePath t finalDir := path.Dir(finalPath) finalDirErr := os.RemoveAll(finalDir) if finalDirErr != nil { - r.Logger.Warnf("Failed to remove finalDir (%v): %q\n", finalDir, finalDirErr) + r.Logger.WithError(finalDirErr).WithField("dir", finalDir).Warn("Failed to remove finalDir") } completeRemoteRequest(activeRemoteRequests, mxcURL) return updateActiveRemoteRequests @@ -418,15 +438,15 @@ func (r *downloadRequest) commitFileAndMetadata(tmpDir types.Path, absBasePath t r.Logger.WithFields(log.Fields{ "Origin": r.MediaMetadata.Origin, "MediaID": r.MediaMetadata.MediaID, - }).Infof("Signalling other goroutines waiting for us to fetch the file.") + }).Info("Signalling other goroutines waiting for us to fetch the file.") completeRemoteRequest(activeRemoteRequests, mxcURL) return updateActiveRemoteRequests } func (r *downloadRequest) respondFromRemoteFile(w http.ResponseWriter, absBasePath types.Path, maxFileSizeBytes types.ContentLength, db *storage.Database, activeRemoteRequests *types.ActiveRemoteRequests) { r.Logger.WithFields(log.Fields{ - "MediaID": r.MediaMetadata.MediaID, "Origin": r.MediaMetadata.Origin, + "MediaID": r.MediaMetadata.MediaID, }).Infof("Fetching remote file") mxcURL := "mxc://" + string(r.MediaMetadata.Origin) + "/" + string(r.MediaMetadata.MediaID) @@ -455,7 +475,7 @@ func (r *downloadRequest) respondFromRemoteFile(w http.ResponseWriter, absBasePa // get metadata from request and set metadata on response contentLength, err := strconv.ParseInt(resp.Header.Get("Content-Length"), 10, 64) if err != nil { - r.Logger.Warn("Failed to parse content length") + r.Logger.WithError(err).Warn("Failed to parse content length") } r.MediaMetadata.ContentLength = types.ContentLength(contentLength) @@ -505,10 +525,10 @@ func (r *downloadRequest) respondFromRemoteFile(w http.ResponseWriter, absBasePa if fetchError == errFileIsTooLarge { logFields["MaxFileSizeBytes"] = maxFileSizeBytes } - r.Logger.WithFields(logFields).Warnln(fetchError) + r.Logger.WithError(fetchError).WithFields(logFields).Warn("Error while fetching file") tmpDirErr := os.RemoveAll(string(tmpDir)) if tmpDirErr != nil { - r.Logger.Warnf("Failed to remove tmpDir (%v): %q\n", tmpDir, tmpDirErr) + r.Logger.WithError(tmpDirErr).WithField("dir", tmpDir).Warn("Failed to remove tmpDir") } // Note: if we have responded with any data in the body at all then we have already sent 200 OK and we can only abort at this point if bytesResponded < 1 { diff --git a/src/github.com/matrix-org/dendrite/mediaapi/writers/fileutils.go b/src/github.com/matrix-org/dendrite/mediaapi/writers/fileutils.go index 1a519e656..2b6bf16be 100644 --- a/src/github.com/matrix-org/dendrite/mediaapi/writers/fileutils.go +++ b/src/github.com/matrix-org/dendrite/mediaapi/writers/fileutils.go @@ -57,7 +57,7 @@ func createFileWriter(directory types.Path, filename types.Filename) (*bufio.Wri func createTempFileWriter(absBasePath types.Path, logger *log.Entry) (*bufio.Writer, *os.File, types.Path, *util.JSONResponse) { tmpDir, err := createTempDir(absBasePath) if err != nil { - logger.Warnf("Failed to create temp dir: %q\n", err) + logger.WithError(err).WithField("dir", tmpDir).Warn("Failed to create temp dir") return nil, nil, "", &util.JSONResponse{ Code: 400, JSON: jsonerror.Unknown(fmt.Sprintf("Failed to upload")), @@ -65,7 +65,7 @@ func createTempFileWriter(absBasePath types.Path, logger *log.Entry) (*bufio.Wri } writer, tmpFile, err := createFileWriter(tmpDir, "content") if err != nil { - logger.Warnf("Failed to create file writer: %q\n", err) + logger.WithError(err).Warn("Failed to create file writer") return nil, nil, "", &util.JSONResponse{ Code: 400, JSON: jsonerror.Unknown(fmt.Sprintf("Failed to upload")), diff --git a/src/github.com/matrix-org/dendrite/mediaapi/writers/upload.go b/src/github.com/matrix-org/dendrite/mediaapi/writers/upload.go index a5f5894cd..38e7c8a61 100644 --- a/src/github.com/matrix-org/dendrite/mediaapi/writers/upload.go +++ b/src/github.com/matrix-org/dendrite/mediaapi/writers/upload.go @@ -97,7 +97,7 @@ type uploadResponse struct { func removeDir(dir types.Path, logger *log.Entry) { dirErr := os.RemoveAll(string(dir)) if dirErr != nil { - logger.Warnf("Failed to remove directory (%v): %q\n", dir, dirErr) + logger.WithError(dirErr).WithField("dir", dir).Warn("Failed to remove directory") } } @@ -168,7 +168,7 @@ func writeFileWithLimitAndHash(r io.Reader, cfg *config.MediaAPI, logger *log.En bytesWritten, err := io.Copy(writer, reader) if err != nil { - logger.Warnf("Failed to copy %q\n", err) + logger.WithError(err).Warn("Failed to copy") removeDir(tmpDir, logger) return nil, "", &util.JSONResponse{ Code: 400, @@ -179,7 +179,10 @@ func writeFileWithLimitAndHash(r io.Reader, cfg *config.MediaAPI, logger *log.En writer.Flush() if bytesWritten != int64(contentLength) { - logger.Warnf("Bytes uploaded (%v) != claimed Content-Length (%v)", bytesWritten, contentLength) + logger.WithFields(log.Fields{ + "bytesWritten": bytesWritten, + "contentLength": contentLength, + }).Warn("Fewer bytes written than expected") } return hasher.Sum(nil), tmpDir, nil @@ -193,7 +196,7 @@ func writeFileWithLimitAndHash(r io.Reader, cfg *config.MediaAPI, logger *log.En func storeFileAndMetadata(tmpDir types.Path, absBasePath types.Path, mediaMetadata *types.MediaMetadata, db *storage.Database, logger *log.Entry) *util.JSONResponse { finalPath, err := getPathFromMediaMetadata(mediaMetadata, absBasePath) if err != nil { - logger.Warnf("Failed to get file path from metadata: %q\n", err) + logger.WithError(err).Warn("Failed to get file path from metadata") removeDir(tmpDir, logger) return &util.JSONResponse{ Code: 400, @@ -206,7 +209,7 @@ func storeFileAndMetadata(tmpDir types.Path, absBasePath types.Path, mediaMetada types.Path(finalPath), ) if err != nil { - logger.Warnf("Failed to move file to final destination: %q\n", err) + logger.WithError(err).WithField("dst", finalPath).Warn("Failed to move file to final destination") removeDir(tmpDir, logger) return &util.JSONResponse{ Code: 400, @@ -216,7 +219,7 @@ func storeFileAndMetadata(tmpDir types.Path, absBasePath types.Path, mediaMetada err = db.StoreMediaMetadata(mediaMetadata) if err != nil { - logger.Warnf("Failed to store metadata: %q\n", err) + logger.WithError(err).Warn("Failed to store metadata") removeDir(types.Path(path.Dir(finalPath)), logger) return &util.JSONResponse{ Code: 400, @@ -279,7 +282,7 @@ func Upload(req *http.Request, cfg *config.MediaAPI, db *storage.Database) util. }, } } else if err != sql.ErrNoRows { - logger.Warnf("Failed to query database for %v: %q", r.MediaMetadata.MediaID, err) + logger.WithError(err).WithField("MediaID", r.MediaMetadata.MediaID).Warn("Failed to query database") } // TODO: generate thumbnails