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 <art27@cantab.net>

Co-authored-by: Lauris BH <lauris@nix.lv>

3 files changed, 149 insertions, 46 deletions

diff --git a/modules/lfs/content_store.go b/modules/lfs/content_store.go
index 895b51b8ba..36e84a31ba 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 b077cd2d0b..ec9da40ec7 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 5899f4dfce..cdbda46214 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) {