From 9269b7f6271e865f2eeda7a68ed8f1afe7431bad Mon Sep 17 00:00:00 2001 From: zeripath Date: Mon, 9 Mar 2020 19:56:18 +0000 Subject: [PATCH] Multiple LFS improvements (#10667) * Add more logging in the LFS server Adds more logging in the LFS server and stops sending internal server error information to the client * Add LFS Lock cursor implementation * Simplify Claims in LFS and remove the float64 casts Signed-off-by: Andrew Thornton Co-authored-by: Lauris BH --- cmd/serv.go | 15 ++- custom/conf/app.ini.sample | 2 + .../doc/advanced/config-cheat-sheet.en-us.md | 1 + modules/lfs/content_store.go | 16 ++- modules/lfs/locks.go | 71 ++++++++++-- modules/lfs/server.go | 108 ++++++++++++------ modules/setting/setting.go | 4 + 7 files changed, 165 insertions(+), 52 deletions(-) diff --git a/cmd/serv.go b/cmd/serv.go index fa1e03339..7c2be5157 100644 --- a/cmd/serv.go +++ b/cmd/serv.go @@ -18,6 +18,7 @@ import ( "time" "code.gitea.io/gitea/models" + "code.gitea.io/gitea/modules/lfs" "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/pprof" "code.gitea.io/gitea/modules/private" @@ -213,12 +214,14 @@ func runServ(c *cli.Context) error { url := fmt.Sprintf("%s%s/%s.git/info/lfs", setting.AppURL, url.PathEscape(results.OwnerName), url.PathEscape(results.RepoName)) now := time.Now() - claims := jwt.MapClaims{ - "repo": results.RepoID, - "op": lfsVerb, - "exp": now.Add(setting.LFS.HTTPAuthExpiry).Unix(), - "nbf": now.Unix(), - "user": results.UserID, + claims := lfs.Claims{ + StandardClaims: jwt.StandardClaims{ + ExpiresAt: now.Add(setting.LFS.HTTPAuthExpiry).Unix(), + NotBefore: now.Unix(), + }, + RepoID: results.RepoID, + Op: lfsVerb, + UserID: results.UserID, } token := jwt.NewWithClaims(jwt.SigningMethodHS256, claims) diff --git a/custom/conf/app.ini.sample b/custom/conf/app.ini.sample index 7fd602831..f83f06bc6 100644 --- a/custom/conf/app.ini.sample +++ b/custom/conf/app.ini.sample @@ -313,6 +313,8 @@ LFS_JWT_SECRET = LFS_HTTP_AUTH_EXPIRY = 20m ; Maximum allowed LFS file size in bytes (Set to 0 for no limit). LFS_MAX_FILE_SIZE = 0 +; Maximum number of locks returned per page +LFS_LOCKS_PAGING_NUM = 50 ; Allow graceful restarts using SIGHUP to fork ALLOW_GRACEFUL_RESTARTS = true ; After a restart the parent will finish ongoing requests before diff --git a/docs/content/doc/advanced/config-cheat-sheet.en-us.md b/docs/content/doc/advanced/config-cheat-sheet.en-us.md index fa8664847..c37873922 100644 --- a/docs/content/doc/advanced/config-cheat-sheet.en-us.md +++ b/docs/content/doc/advanced/config-cheat-sheet.en-us.md @@ -193,6 +193,7 @@ Values containing `#` or `;` must be quoted using `` ` `` or `"""`. - `LFS_JWT_SECRET`: **\**: LFS authentication secret, change this a unique string. - `LFS_HTTP_AUTH_EXPIRY`: **20m**: LFS authentication validity period in time.Duration, pushes taking longer than this may fail. - `LFS_MAX_FILE_SIZE`: **0**: Maximum allowed LFS file size in bytes (Set to 0 for no limit). +- `LFS_LOCK_PAGING_NUM`: **50**: Maximum number of LFS Locks returned per page. - `REDIRECT_OTHER_PORT`: **false**: If true and `PROTOCOL` is https, allows redirecting http requests on `PORT_TO_REDIRECT` to the https port Gitea listens on. - `PORT_TO_REDIRECT`: **80**: Port for the http redirection service to listen on. Used when `REDIRECT_OTHER_PORT` is true. - `ENABLE_LETSENCRYPT`: **false**: If enabled you must set `DOMAIN` to valid internet facing domain (ensure DNS is set and port 80 is accessible by letsencrypt validation server). diff --git a/modules/lfs/content_store.go b/modules/lfs/content_store.go index 895b51b8b..36e84a31b 100644 --- a/modules/lfs/content_store.go +++ b/modules/lfs/content_store.go @@ -9,6 +9,7 @@ import ( "path/filepath" "code.gitea.io/gitea/models" + "code.gitea.io/gitea/modules/log" ) var ( @@ -28,10 +29,14 @@ func (s *ContentStore) Get(meta *models.LFSMetaObject, fromByte int64) (io.ReadC f, err := os.Open(path) if err != nil { + log.Error("Whilst trying to read LFS OID[%s]: Unable to open %s Error: %v", meta.Oid, path, err) return nil, err } if fromByte > 0 { _, err = f.Seek(fromByte, os.SEEK_CUR) + if err != nil { + log.Error("Whilst trying to read LFS OID[%s]: Unable to seek to %d Error: %v", meta.Oid, fromByte, err) + } } return f, err } @@ -43,11 +48,13 @@ func (s *ContentStore) Put(meta *models.LFSMetaObject, r io.Reader) error { dir := filepath.Dir(path) if err := os.MkdirAll(dir, 0750); err != nil { + log.Error("Whilst putting LFS OID[%s]: Unable to create the LFS directory: %s Error: %v", meta.Oid, dir, err) return err } file, err := os.OpenFile(tmpPath, os.O_CREATE|os.O_WRONLY|os.O_EXCL, 0640) if err != nil { + log.Error("Whilst putting LFS OID[%s]: Unable to open temporary file for writing: %s Error: %v", tmpPath, err) return err } defer os.Remove(tmpPath) @@ -57,6 +64,7 @@ func (s *ContentStore) Put(meta *models.LFSMetaObject, r io.Reader) error { written, err := io.Copy(hw, r) if err != nil { + log.Error("Whilst putting LFS OID[%s]: Failed to copy to tmpPath: %s Error: %v", meta.Oid, tmpPath, err) file.Close() return err } @@ -71,7 +79,12 @@ func (s *ContentStore) Put(meta *models.LFSMetaObject, r io.Reader) error { return errHashMismatch } - return os.Rename(tmpPath, path) + if err := os.Rename(tmpPath, path); err != nil { + log.Error("Whilst putting LFS OID[%s]: Unable to move tmp file to final destination: %s Error: %v", meta.Oid, path, err) + return err + } + + return nil } // Exists returns true if the object exists in the content store. @@ -91,6 +104,7 @@ func (s *ContentStore) Verify(meta *models.LFSMetaObject) (bool, error) { if os.IsNotExist(err) || err == nil && fi.Size() != meta.Size { return false, nil } else if err != nil { + log.Error("Unable stat file: %s for LFS OID[%s] Error: %v", path, meta.Oid, err) return false, err } diff --git a/modules/lfs/locks.go b/modules/lfs/locks.go index b077cd2d0..ec9da40ec 100644 --- a/modules/lfs/locks.go +++ b/modules/lfs/locks.go @@ -19,10 +19,12 @@ import ( //checkIsValidRequest check if it a valid request in case of bad request it write the response to ctx. func checkIsValidRequest(ctx *context.Context) bool { if !setting.LFS.StartServer { + log.Debug("Attempt to access LFS server but LFS server is disabled") writeStatus(ctx, 404) return false } if !MetaMatcher(ctx.Req) { + log.Info("Attempt access LOCKs without accepting the correct media type: %s", metaMediaType) writeStatus(ctx, 400) return false } @@ -47,7 +49,7 @@ func handleLockListOut(ctx *context.Context, repo *models.Repository, lock *mode return } ctx.JSON(500, api.LFSLockError{ - Message: "unable to list locks : " + err.Error(), + Message: "unable to list locks : Internal Server Error", }) return } @@ -65,6 +67,7 @@ func handleLockListOut(ctx *context.Context, repo *models.Repository, lock *mode // GetListLockHandler list locks func GetListLockHandler(ctx *context.Context) { if !checkIsValidRequest(ctx) { + // Status is written in checkIsValidRequest return } ctx.Resp.Header().Set("Content-Type", metaMediaType) @@ -87,7 +90,17 @@ func GetListLockHandler(ctx *context.Context) { }) return } - //TODO handle query cursor and limit + + cursor := ctx.QueryInt("cursor") + if cursor < 0 { + cursor = 0 + } + limit := ctx.QueryInt("limit") + if limit > setting.LFS.LocksPagingNum && setting.LFS.LocksPagingNum > 0 { + limit = setting.LFS.LocksPagingNum + } else if limit < 0 { + limit = 0 + } id := ctx.Query("id") if id != "" { //Case where we request a specific id v, err := strconv.ParseInt(id, 10, 64) @@ -98,6 +111,9 @@ func GetListLockHandler(ctx *context.Context) { return } lock, err := models.GetLFSLockByID(v) + if err != nil && !models.IsErrLFSLockNotExist(err) { + log.Error("Unable to get lock with ID[%s]: Error: %v", v, err) + } handleLockListOut(ctx, repository, lock, err) return } @@ -105,30 +121,40 @@ func GetListLockHandler(ctx *context.Context) { path := ctx.Query("path") if path != "" { //Case where we request a specific id lock, err := models.GetLFSLock(repository, path) + if err != nil && !models.IsErrLFSLockNotExist(err) { + log.Error("Unable to get lock for repository %-v with path %s: Error: %v", repository, path, err) + } handleLockListOut(ctx, repository, lock, err) return } //If no query params path or id - lockList, err := models.GetLFSLockByRepoID(repository.ID, 0, 0) + lockList, err := models.GetLFSLockByRepoID(repository.ID, cursor, limit) if err != nil { + log.Error("Unable to list locks for repository ID[%d]: Error: %v", repository.ID, err) ctx.JSON(500, api.LFSLockError{ - Message: "unable to list locks : " + err.Error(), + Message: "unable to list locks : Internal Server Error", }) return } lockListAPI := make([]*api.LFSLock, len(lockList)) + next := "" for i, l := range lockList { lockListAPI[i] = l.APIFormat() } + if limit > 0 && len(lockList) == limit { + next = strconv.Itoa(cursor + 1) + } ctx.JSON(200, api.LFSLockList{ Locks: lockListAPI, + Next: next, }) } // PostLockHandler create lock func PostLockHandler(ctx *context.Context) { if !checkIsValidRequest(ctx) { + // Status is written in checkIsValidRequest return } ctx.Resp.Header().Set("Content-Type", metaMediaType) @@ -139,7 +165,7 @@ func PostLockHandler(ctx *context.Context) { repository, err := models.GetRepositoryByOwnerAndName(userName, repoName) if err != nil { - log.Debug("Could not find repository: %s/%s - %s", userName, repoName, err) + log.Error("Unable to get repository: %s/%s Error: %v", userName, repoName, err) writeStatus(ctx, 404) return } @@ -159,6 +185,7 @@ func PostLockHandler(ctx *context.Context) { defer bodyReader.Close() dec := json.NewDecoder(bodyReader) if err := dec.Decode(&req); err != nil { + log.Warn("Failed to decode lock request as json. Error: %v", err) writeStatus(ctx, 400) return } @@ -183,8 +210,9 @@ func PostLockHandler(ctx *context.Context) { }) return } + log.Error("Unable to CreateLFSLock in repository %-v at %s for user %-v: Error: %v", repository, req.Path, ctx.User, err) ctx.JSON(500, api.LFSLockError{ - Message: "internal server error : " + err.Error(), + Message: "internal server error : Internal Server Error", }) return } @@ -194,6 +222,7 @@ func PostLockHandler(ctx *context.Context) { // VerifyLockHandler list locks for verification func VerifyLockHandler(ctx *context.Context) { if !checkIsValidRequest(ctx) { + // Status is written in checkIsValidRequest return } ctx.Resp.Header().Set("Content-Type", metaMediaType) @@ -204,7 +233,7 @@ func VerifyLockHandler(ctx *context.Context) { repository, err := models.GetRepositoryByOwnerAndName(userName, repoName) if err != nil { - log.Debug("Could not find repository: %s/%s - %s", userName, repoName, err) + log.Error("Unable to get repository: %s/%s Error: %v", userName, repoName, err) writeStatus(ctx, 404) return } @@ -219,14 +248,28 @@ func VerifyLockHandler(ctx *context.Context) { return } - //TODO handle body json cursor and limit - lockList, err := models.GetLFSLockByRepoID(repository.ID, 0, 0) + cursor := ctx.QueryInt("cursor") + if cursor < 0 { + cursor = 0 + } + limit := ctx.QueryInt("limit") + if limit > setting.LFS.LocksPagingNum && setting.LFS.LocksPagingNum > 0 { + limit = setting.LFS.LocksPagingNum + } else if limit < 0 { + limit = 0 + } + lockList, err := models.GetLFSLockByRepoID(repository.ID, cursor, limit) if err != nil { + log.Error("Unable to list locks for repository ID[%d]: Error: %v", repository.ID, err) ctx.JSON(500, api.LFSLockError{ - Message: "unable to list locks : " + err.Error(), + Message: "unable to list locks : Internal Server Error", }) return } + next := "" + if limit > 0 && len(lockList) == limit { + next = strconv.Itoa(cursor + 1) + } lockOursListAPI := make([]*api.LFSLock, 0, len(lockList)) lockTheirsListAPI := make([]*api.LFSLock, 0, len(lockList)) for _, l := range lockList { @@ -239,12 +282,14 @@ func VerifyLockHandler(ctx *context.Context) { ctx.JSON(200, api.LFSLockListVerify{ Ours: lockOursListAPI, Theirs: lockTheirsListAPI, + Next: next, }) } // UnLockHandler delete locks func UnLockHandler(ctx *context.Context) { if !checkIsValidRequest(ctx) { + // Status is written in checkIsValidRequest return } ctx.Resp.Header().Set("Content-Type", metaMediaType) @@ -255,7 +300,7 @@ func UnLockHandler(ctx *context.Context) { repository, err := models.GetRepositoryByOwnerAndName(userName, repoName) if err != nil { - log.Debug("Could not find repository: %s/%s - %s", userName, repoName, err) + log.Error("Unable to get repository: %s/%s Error: %v", userName, repoName, err) writeStatus(ctx, 404) return } @@ -275,6 +320,7 @@ func UnLockHandler(ctx *context.Context) { defer bodyReader.Close() dec := json.NewDecoder(bodyReader) if err := dec.Decode(&req); err != nil { + log.Warn("Failed to decode lock request as json. Error: %v", err) writeStatus(ctx, 400) return } @@ -288,8 +334,9 @@ func UnLockHandler(ctx *context.Context) { }) return } + log.Error("Unable to DeleteLFSLockByID[%d] by user %-v with force %t: Error: %v", ctx.ParamsInt64("lid"), ctx.User, req.Force, err) ctx.JSON(500, api.LFSLockError{ - Message: "unable to delete lock : " + err.Error(), + Message: "unable to delete lock : Internal Server Error", }) return } diff --git a/modules/lfs/server.go b/modules/lfs/server.go index 5899f4dfc..cdbda4621 100644 --- a/modules/lfs/server.go +++ b/modules/lfs/server.go @@ -65,6 +65,14 @@ type ObjectError struct { Message string `json:"message"` } +// Claims is a JWT Token Claims +type Claims struct { + RepoID int64 + Op string + UserID int64 + jwt.StandardClaims +} + // ObjectLink builds a URL linking to the object. func (v *RequestVars) ObjectLink() string { return setting.AppURL + path.Join(v.User, v.Repo+".git", "info/lfs/objects", v.Oid) @@ -91,6 +99,7 @@ func isOidValid(oid string) bool { // ObjectOidHandler is the main request routing entry point into LFS server functions func ObjectOidHandler(ctx *context.Context) { if !setting.LFS.StartServer { + log.Debug("Attempt to access LFS server but LFS server is disabled") writeStatus(ctx, 404) return } @@ -108,17 +117,20 @@ func ObjectOidHandler(ctx *context.Context) { return } + log.Warn("Unhandled LFS method: %s for %s/%s OID[%s]", ctx.Req.Method, ctx.Params("username"), ctx.Params("reponame"), ctx.Params("oid")) + writeStatus(ctx, 404) } func getAuthenticatedRepoAndMeta(ctx *context.Context, rv *RequestVars, requireWrite bool) (*models.LFSMetaObject, *models.Repository) { if !isOidValid(rv.Oid) { + log.Info("Attempt to access invalid LFS OID[%s] in %s/%s", rv.Oid, rv.User, rv.Repo) writeStatus(ctx, 404) return nil, nil } repository, err := models.GetRepositoryByOwnerAndName(rv.User, rv.Repo) if err != nil { - log.Debug("Could not find repository: %s/%s - %s", rv.User, rv.Repo, err) + log.Error("Unable to get repository: %s/%s Error: %v", rv.User, rv.Repo, err) writeStatus(ctx, 404) return nil, nil } @@ -130,6 +142,7 @@ func getAuthenticatedRepoAndMeta(ctx *context.Context, rv *RequestVars, requireW meta, err := repository.GetLFSMetaObjectByOid(rv.Oid) if err != nil { + log.Error("Unable to get LFS OID[%s] Error: %v", rv.Oid, err) writeStatus(ctx, 404) return nil, nil } @@ -143,6 +156,7 @@ func getContentHandler(ctx *context.Context) { meta, _ := getAuthenticatedRepoAndMeta(ctx, rv, false) if meta == nil { + // Status already written in getAuthenticatedRepoAndMeta return } @@ -162,9 +176,11 @@ func getContentHandler(ctx *context.Context) { contentStore := &ContentStore{BasePath: setting.LFS.ContentPath} content, err := contentStore.Get(meta, fromByte) if err != nil { + // Errors are logged in contentStore.Get writeStatus(ctx, 404) return } + defer content.Close() ctx.Resp.Header().Set("Content-Length", strconv.FormatInt(meta.Size-fromByte, 10)) ctx.Resp.Header().Set("Content-Type", "application/octet-stream") @@ -178,8 +194,9 @@ func getContentHandler(ctx *context.Context) { } ctx.Resp.WriteHeader(statusCode) - _, _ = io.Copy(ctx.Resp, content) - _ = content.Close() + if written, err := io.Copy(ctx.Resp, content); err != nil { + log.Error("Error whilst copying LFS OID[%s] to the response after %d bytes. Error: %v", meta.Oid, written, err) + } logRequest(ctx.Req, statusCode) } @@ -189,6 +206,7 @@ func getMetaHandler(ctx *context.Context) { meta, _ := getAuthenticatedRepoAndMeta(ctx, rv, false) if meta == nil { + // Status already written in getAuthenticatedRepoAndMeta return } @@ -196,7 +214,9 @@ func getMetaHandler(ctx *context.Context) { if ctx.Req.Method == "GET" { enc := json.NewEncoder(ctx.Resp) - _ = enc.Encode(Represent(rv, meta, true, false)) + if err := enc.Encode(Represent(rv, meta, true, false)); err != nil { + log.Error("Failed to encode representation as json. Error: %v", err) + } } logRequest(ctx.Req, 200) @@ -205,11 +225,13 @@ func getMetaHandler(ctx *context.Context) { // PostHandler instructs the client how to upload data func PostHandler(ctx *context.Context) { if !setting.LFS.StartServer { + log.Debug("Attempt to access LFS server but LFS server is disabled") writeStatus(ctx, 404) return } if !MetaMatcher(ctx.Req) { + log.Info("Attempt to POST without accepting the correct media type: %s", metaMediaType) writeStatus(ctx, 400) return } @@ -218,7 +240,7 @@ func PostHandler(ctx *context.Context) { repository, err := models.GetRepositoryByOwnerAndName(rv.User, rv.Repo) if err != nil { - log.Debug("Could not find repository: %s/%s - %s", rv.User, rv.Repo, err) + log.Error("Unable to get repository: %s/%s Error: %v", rv.User, rv.Repo, err) writeStatus(ctx, 404) return } @@ -229,18 +251,20 @@ func PostHandler(ctx *context.Context) { } if !isOidValid(rv.Oid) { + log.Info("Invalid LFS OID[%s] attempt to POST in %s/%s", rv.Oid, rv.User, rv.Repo) writeStatus(ctx, 404) return } if setting.LFS.MaxFileSize > 0 && rv.Size > setting.LFS.MaxFileSize { - log.Info("Denied LFS upload of size %d to %s/%s because of LFS_MAX_FILE_SIZE=%d", rv.Size, rv.User, rv.Repo, setting.LFS.MaxFileSize) + log.Info("Denied LFS OID[%s] upload of size %d to %s/%s because of LFS_MAX_FILE_SIZE=%d", rv.Oid, rv.Size, rv.User, rv.Repo, setting.LFS.MaxFileSize) writeStatus(ctx, 413) return } meta, err := models.NewLFSMetaObject(&models.LFSMetaObject{Oid: rv.Oid, Size: rv.Size, RepositoryID: repository.ID}) if err != nil { + log.Error("Unable to write LFS OID[%s] size %d meta object in %v/%v to database. Error: %v", rv.Oid, rv.Size, rv.User, rv.Repo, err) writeStatus(ctx, 404) return } @@ -255,18 +279,22 @@ func PostHandler(ctx *context.Context) { ctx.Resp.WriteHeader(sentStatus) enc := json.NewEncoder(ctx.Resp) - _ = enc.Encode(Represent(rv, meta, meta.Existing, true)) + if err := enc.Encode(Represent(rv, meta, meta.Existing, true)); err != nil { + log.Error("Failed to encode representation as json. Error: %v", err) + } logRequest(ctx.Req, sentStatus) } // BatchHandler provides the batch api func BatchHandler(ctx *context.Context) { if !setting.LFS.StartServer { + log.Debug("Attempt to access LFS server but LFS server is disabled") writeStatus(ctx, 404) return } if !MetaMatcher(ctx.Req) { + log.Info("Attempt to BATCH without accepting the correct media type: %s", metaMediaType) writeStatus(ctx, 400) return } @@ -278,13 +306,13 @@ func BatchHandler(ctx *context.Context) { // Create a response object for _, object := range bv.Objects { if !isOidValid(object.Oid) { + log.Info("Invalid LFS OID[%s] attempt to BATCH in %s/%s", object.Oid, object.User, object.Repo) continue } repository, err := models.GetRepositoryByOwnerAndName(object.User, object.Repo) - if err != nil { - log.Debug("Could not find repository: %s/%s - %s", object.User, object.Repo, err) + log.Error("Unable to get repository: %s/%s Error: %v", object.User, object.Repo, err) writeStatus(ctx, 404) return } @@ -308,7 +336,7 @@ func BatchHandler(ctx *context.Context) { } if requireWrite && setting.LFS.MaxFileSize > 0 && object.Size > setting.LFS.MaxFileSize { - log.Info("Denied LFS upload of size %d to %s/%s because of LFS_MAX_FILE_SIZE=%d", object.Size, object.User, object.Repo, setting.LFS.MaxFileSize) + log.Info("Denied LFS OID[%s] upload of size %d to %s/%s because of LFS_MAX_FILE_SIZE=%d", object.Oid, object.Size, object.User, object.Repo, setting.LFS.MaxFileSize) writeStatus(ctx, 413) return } @@ -317,6 +345,8 @@ func BatchHandler(ctx *context.Context) { meta, err = models.NewLFSMetaObject(&models.LFSMetaObject{Oid: object.Oid, Size: object.Size, RepositoryID: repository.ID}) if err == nil { responseObjects = append(responseObjects, Represent(object, meta, meta.Existing, !contentStore.Exists(meta))) + } else { + log.Error("Unable to write LFS OID[%s] size %d meta object in %v/%v to database. Error: %v", object.Oid, object.Size, object.User, object.Repo, err) } } @@ -325,7 +355,9 @@ func BatchHandler(ctx *context.Context) { respobj := &BatchResponse{Objects: responseObjects} enc := json.NewEncoder(ctx.Resp) - _ = enc.Encode(respobj) + if err := enc.Encode(respobj); err != nil { + log.Error("Failed to encode representation as json. Error: %v", err) + } logRequest(ctx.Req, 200) } @@ -335,6 +367,7 @@ func PutHandler(ctx *context.Context) { meta, repository := getAuthenticatedRepoAndMeta(ctx, rv, true) if meta == nil { + // Status already written in getAuthenticatedRepoAndMeta return } @@ -342,10 +375,15 @@ func PutHandler(ctx *context.Context) { bodyReader := ctx.Req.Body().ReadCloser() defer bodyReader.Close() if err := contentStore.Put(meta, bodyReader); err != nil { + // Put will log the error itself ctx.Resp.WriteHeader(500) - fmt.Fprintf(ctx.Resp, `{"message":"%s"}`, err) + if err == errSizeMismatch || err == errHashMismatch { + fmt.Fprintf(ctx.Resp, `{"message":"%s"}`, err) + } else { + fmt.Fprintf(ctx.Resp, `{"message":"Internal Server Error"}`) + } if _, err = repository.RemoveLFSMetaObjectByOid(rv.Oid); err != nil { - log.Error("RemoveLFSMetaObjectByOid: %v", err) + log.Error("Whilst removing metaobject for LFS OID[%s] due to preceding error there was another Error: %v", rv.Oid, err) } return } @@ -356,11 +394,13 @@ func PutHandler(ctx *context.Context) { // VerifyHandler verify oid and its size from the content store func VerifyHandler(ctx *context.Context) { if !setting.LFS.StartServer { + log.Debug("Attempt to access LFS server but LFS server is disabled") writeStatus(ctx, 404) return } if !MetaMatcher(ctx.Req) { + log.Info("Attempt to VERIFY without accepting the correct media type: %s", metaMediaType) writeStatus(ctx, 400) return } @@ -369,14 +409,16 @@ func VerifyHandler(ctx *context.Context) { meta, _ := getAuthenticatedRepoAndMeta(ctx, rv, true) if meta == nil { + // Status already written in getAuthenticatedRepoAndMeta return } contentStore := &ContentStore{BasePath: setting.LFS.ContentPath} ok, err := contentStore.Verify(meta) if err != nil { + // Error will be logged in Verify ctx.Resp.WriteHeader(500) - fmt.Fprintf(ctx.Resp, `{"message":"%s"}`, err) + fmt.Fprintf(ctx.Resp, `{"message":"Internal Server Error"}`) return } if !ok { @@ -453,6 +495,8 @@ func unpack(ctx *context.Context) *RequestVars { dec := json.NewDecoder(bodyReader) err := dec.Decode(&p) if err != nil { + // The error is logged as a WARN here because this may represent misbehaviour rather than a true error + log.Warn("Unable to decode POST request vars for LFS OID[%s] in %s/%s: Error: %v", rv.Oid, rv.User, rv.Repo, err) return rv } @@ -474,6 +518,8 @@ func unpackbatch(ctx *context.Context) *BatchVars { dec := json.NewDecoder(bodyReader) err := dec.Decode(&bv) if err != nil { + // The error is logged as a WARN here because this may represent misbehaviour rather than a true error + log.Warn("Unable to decode BATCH request vars in %s/%s: Error: %v", ctx.Params("username"), strings.TrimSuffix(ctx.Params("reponame"), ".git"), err) return &bv } @@ -515,6 +561,7 @@ func authenticate(ctx *context.Context, repository *models.Repository, authoriza // ctx.IsSigned is unnecessary here, this will be checked in perm.CanAccess perm, err := models.GetUserRepoPermission(repository, ctx.User) if err != nil { + log.Error("Unable to GetUserRepoPermission for user %-v in repo %-v Error: %v", ctx.User, repository) return false } @@ -525,12 +572,15 @@ func authenticate(ctx *context.Context, repository *models.Repository, authoriza user, repo, opStr, err := parseToken(authorization) if err != nil { + // Most of these are Warn level - the true internal server errors are logged in parseToken already + log.Warn("Authentication failure for provided token with Error: %v", err) return false } ctx.User = user if opStr == "basic" { perm, err = models.GetUserRepoPermission(repository, ctx.User) if err != nil { + log.Error("Unable to GetUserRepoPermission for user %-v in repo %-v Error: %v", ctx.User, repository) return false } return perm.CanAccess(accessMode, models.UnitTypeCode) @@ -549,40 +599,31 @@ func parseToken(authorization string) (*models.User, *models.Repository, string, return nil, nil, "unknown", fmt.Errorf("No token") } if strings.HasPrefix(authorization, "Bearer ") { - token, err := jwt.Parse(authorization[7:], func(t *jwt.Token) (interface{}, error) { + token, err := jwt.ParseWithClaims(authorization[7:], &Claims{}, func(t *jwt.Token) (interface{}, error) { if _, ok := t.Method.(*jwt.SigningMethodHMAC); !ok { return nil, fmt.Errorf("unexpected signing method: %v", t.Header["alg"]) } return setting.LFS.JWTSecretBytes, nil }) if err != nil { + // The error here is WARN level because it is caused by bad authorization rather than an internal server error return nil, nil, "unknown", err } - claims, claimsOk := token.Claims.(jwt.MapClaims) + claims, claimsOk := token.Claims.(*Claims) if !token.Valid || !claimsOk { return nil, nil, "unknown", fmt.Errorf("Token claim invalid") } - opStr, ok := claims["op"].(string) - if !ok { - return nil, nil, "unknown", fmt.Errorf("Token operation invalid") - } - repoID, ok := claims["repo"].(float64) - if !ok { - return nil, nil, opStr, fmt.Errorf("Token repository id invalid") - } - r, err := models.GetRepositoryByID(int64(repoID)) + r, err := models.GetRepositoryByID(claims.RepoID) if err != nil { - return nil, nil, opStr, err - } - userID, ok := claims["user"].(float64) - if !ok { - return nil, r, opStr, fmt.Errorf("Token user id invalid") + log.Error("Unable to GetRepositoryById[%d]: Error: %v", claims.RepoID, err) + return nil, nil, claims.Op, err } - u, err := models.GetUserByID(int64(userID)) + u, err := models.GetUserByID(claims.UserID) if err != nil { - return nil, r, opStr, err + log.Error("Unable to GetUserById[%d]: Error: %v", claims.UserID, err) + return nil, r, claims.Op, err } - return u, r, opStr, nil + return u, r, claims.Op, nil } if strings.HasPrefix(authorization, "Basic ") { @@ -598,6 +639,7 @@ func parseToken(authorization string) (*models.User, *models.Repository, string, user, password := cs[:i], cs[i+1:] u, err := models.GetUserByName(user) if err != nil { + log.Error("Unable to GetUserByName[%d]: Error: %v", user, err) return nil, nil, "basic", err } if !u.IsPasswordSet() || !u.ValidatePassword(password) { diff --git a/modules/setting/setting.go b/modules/setting/setting.go index 64051ce21..74f6da38d 100644 --- a/modules/setting/setting.go +++ b/modules/setting/setting.go @@ -141,6 +141,7 @@ var ( JWTSecretBytes []byte `ini:"-"` HTTPAuthExpiry time.Duration `ini:"LFS_HTTP_AUTH_EXPIRY"` MaxFileSize int64 `ini:"LFS_MAX_FILE_SIZE"` + LocksPagingNum int `ini:"LFS_LOCKS_PAGING_NUM"` } // Security settings @@ -720,6 +721,9 @@ func NewContext() { if !filepath.IsAbs(LFS.ContentPath) { LFS.ContentPath = filepath.Join(AppWorkPath, LFS.ContentPath) } + if LFS.LocksPagingNum == 0 { + LFS.LocksPagingNum = 50 + } LFS.HTTPAuthExpiry = sec.Key("LFS_HTTP_AUTH_EXPIRY").MustDuration(20 * time.Minute)