From bef2ed7431632b242fb2710cfe395cfbf0f29a99 Mon Sep 17 00:00:00 2001 From: Derrick Hammer Date: Fri, 19 May 2023 09:04:47 -0400 Subject: [PATCH] refactor: add logging --- controller/account.go | 7 +++++ controller/auth.go | 67 ++++++++++++++++++++++++++++++++---------- controller/files.go | 22 +++++++++----- main.go | 3 +- service/files/files.go | 17 +++++++++-- tus/tus.go | 27 +++++++++++------ 6 files changed, 109 insertions(+), 34 deletions(-) diff --git a/controller/account.go b/controller/account.go index cef42cf..ce72822 100644 --- a/controller/account.go +++ b/controller/account.go @@ -6,9 +6,11 @@ import ( "errors" "git.lumeweb.com/LumeWeb/portal/db" "git.lumeweb.com/LumeWeb/portal/model" + "git.lumeweb.com/LumeWeb/portal/shared" _validator "git.lumeweb.com/LumeWeb/portal/validator" "github.com/go-playground/validator/v10" "github.com/kataras/iris/v12" + "go.uber.org/zap" "golang.org/x/crypto/bcrypt" "gorm.io/gorm" "reflect" @@ -57,6 +59,7 @@ func hashPassword(password string) (string, error) { // Generate a new bcrypt hash from the provided password. hashedPassword, err := bcrypt.GenerateFromPassword([]byte(password), bcrypt.DefaultCost) if err != nil { + shared.GetLogger().Error("failed to hash password", zap.Error(err)) return "", err } @@ -68,6 +71,7 @@ func (a *AccountController) PostRegister() { var r RegisterRequest if err := a.Ctx.ReadJSON(&r); err != nil { + shared.GetLogger().Debug("failed to parse request", zap.Error(err)) a.Ctx.StopWithError(iris.StatusBadRequest, err) return } @@ -76,11 +80,13 @@ func (a *AccountController) PostRegister() { existingAccount := model.Account{} err := db.Get().Where("email = ?", r.Email).First(&existingAccount).Error if err == nil { + shared.GetLogger().Debug("account with email already exists", zap.Error(err), zap.String("email", r.Email)) // An account with the same email address already exists. // Return an error response to the client. a.Ctx.StopWithError(iris.StatusConflict, errors.New("an account with this email address already exists")) return } else if !errors.Is(err, gorm.ErrRecordNotFound) { + shared.GetLogger().Error("error querying accounts", zap.Error(err), zap.String("email", r.Email)) // An unexpected error occurred while querying the database. // Return an error response to the client. a.Ctx.StopWithError(iris.StatusInternalServerError, err) @@ -119,6 +125,7 @@ func (a *AccountController) PostRegister() { return nil }) if err != nil { + shared.GetLogger().Error("failed to create account", zap.Error(err)) a.Ctx.StopWithError(iris.StatusInternalServerError, err) return } diff --git a/controller/auth.go b/controller/auth.go index 1ad1013..10ba918 100644 --- a/controller/auth.go +++ b/controller/auth.go @@ -7,9 +7,11 @@ import ( "fmt" "git.lumeweb.com/LumeWeb/portal/db" "git.lumeweb.com/LumeWeb/portal/model" + "git.lumeweb.com/LumeWeb/portal/shared" "github.com/joomcode/errorx" "github.com/kataras/iris/v12" "github.com/kataras/jwt" + "go.uber.org/zap" "golang.org/x/crypto/bcrypt" "time" ) @@ -73,6 +75,7 @@ func generateToken(maxAge time.Duration) (string, error) { token, err := jwt.Sign(jwt.HS256, sharedKey, claim, jwt.MaxAge(maxAge)) if err != nil { + shared.GetLogger().Error("failed to sign jwt", zap.Error(err)) return "", err } @@ -83,6 +86,7 @@ func generateAndSaveLoginToken(accountID uint, maxAge time.Duration) (string, er // Generate a JWT token for the authenticated user. token, err := generateToken(maxAge) if err != nil { + shared.GetLogger().Error("failed to generate token", zap.Error(err)) return "", fmt.Errorf("failed to generate token: %s", err) } @@ -99,7 +103,9 @@ func generateAndSaveLoginToken(accountID uint, maxAge time.Duration) (string, er } if err := db.Get().Create(&session).Error; err != nil { - return "", errorx.Decorate(err, "failed to save token") + msg := "failed to save token" + shared.GetLogger().Error(msg, zap.Error(err)) + return "", errorx.Decorate(err, msg) } return token, nil @@ -109,6 +115,7 @@ func generateAndSaveChallengeToken(accountID uint, maxAge time.Duration) (string // Generate a JWT token for the authenticated user. token, err := generateToken(maxAge) if err != nil { + shared.GetLogger().Error("failed to generate token", zap.Error(err)) return "", fmt.Errorf("failed to generate token: %s", err) } @@ -125,7 +132,9 @@ func generateAndSaveChallengeToken(accountID uint, maxAge time.Duration) (string } if err := db.Get().Create(&keyChallenge).Error; err != nil { - return "", errorx.Decorate(err, "failed to save token") + msg := "failed to save token" + shared.GetLogger().Error(msg, zap.Error(err)) + return "", errorx.Decorate(err, msg) } return token, nil @@ -137,6 +146,7 @@ func (a *AuthController) PostLogin() { // Read the login request from the client. if err := a.Ctx.ReadJSON(&r); err != nil { + shared.GetLogger().Debug("failed to parse request", zap.Error(err)) a.Ctx.StopWithError(iris.StatusBadRequest, err) return } @@ -144,19 +154,24 @@ func (a *AuthController) PostLogin() { // Retrieve the account for the given email. account := model.Account{} if err := db.Get().Where("email = ?", r.Email).First(&account).Error; err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errors.New("invalid email or password")) + msg := "invalid email or password" + shared.GetLogger().Debug(msg, zap.Error(err)) + a.Ctx.StopWithError(iris.StatusBadRequest, errors.New(msg)) return } // Verify the provided password against the hashed password stored in the database. if err := verifyPassword(*account.Password, r.Password); err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errors.New("invalid email or password")) + msg := "invalid email or password" + shared.GetLogger().Debug(msg, zap.Error(err)) + a.Ctx.StopWithError(iris.StatusBadRequest, errors.New(msg)) return } // Generate a JWT token for the authenticated user. token, err := generateAndSaveLoginToken(account.ID, 24*time.Hour) if err != nil { + shared.GetLogger().Debug("failed to generate token", zap.Error(err)) a.Ctx.StopWithError(iris.StatusInternalServerError, fmt.Errorf("failed to generate token: %s", err)) return } @@ -164,7 +179,7 @@ func (a *AuthController) PostLogin() { // Return the JWT token to the client. err = a.Ctx.JSON(&LoginResponse{Token: token}) if err != nil { - panic(fmt.Errorf("Error with login attempt: %s \n", err)) + shared.GetLogger().Error("failed to generate response", zap.Error(err)) } } @@ -174,6 +189,7 @@ func (a *AuthController) PostPubkeyChallenge() { // Read the login request from the client. if err := a.Ctx.ReadJSON(&r); err != nil { + shared.GetLogger().Debug("failed to parse request", zap.Error(err)) a.Ctx.StopWithError(iris.StatusBadRequest, err) return } @@ -205,6 +221,7 @@ func (a *AuthController) PostPubkeyLogin() { // Read the key login request from the client. if err := a.Ctx.ReadJSON(&r); err != nil { + shared.GetLogger().Debug("failed to parse request", zap.Error(err)) a.Ctx.StopWithError(iris.StatusBadRequest, err) return } @@ -212,25 +229,33 @@ func (a *AuthController) PostPubkeyLogin() { // Retrieve the key challenge for the given challenge. challenge := model.KeyChallenge{} if err := db.Get().Where("challenge = ?", r.Challenge).Preload("Key").First(&challenge).Error; err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("invalid key challenge")) + msg := "invalid key challenge" + shared.GetLogger().Debug(msg, zap.Error(err), zap.String("challenge", r.Challenge)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) return } verifiedToken, err := jwt.Verify(jwt.HS256, sharedKey, []byte(r.Challenge), blocklist) if err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("invalid key challenge")) + msg := "invalid key challenge" + shared.GetLogger().Debug(msg, zap.Error(err), zap.String("challenge", r.Challenge)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) return } rawPubKey, err := hex.DecodeString(r.Pubkey) if err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("invalid pubkey")) + msg := "invalid pubkey" + shared.GetLogger().Debug(msg, zap.Error(err), zap.String("pubkey", r.Pubkey)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) return } rawSignature, err := hex.DecodeString(r.Signature) if err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("invalid signature")) + msg := "invalid signature" + shared.GetLogger().Debug(msg, zap.Error(err), zap.String("signature", r.Signature)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) return } @@ -238,7 +263,9 @@ func (a *AuthController) PostPubkeyLogin() { // Verify the challenge signature. if !ed25519.Verify(publicKeyDecoded, []byte(r.Challenge), rawSignature) { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("invalid challenge")) + msg := "invalid challenge" + shared.GetLogger().Debug(msg, zap.Error(err), zap.String("challenge", r.Challenge)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) } // Generate a JWT token for the authenticated user. @@ -250,19 +277,23 @@ func (a *AuthController) PostPubkeyLogin() { err = blocklist.InvalidateToken(verifiedToken.Token, verifiedToken.StandardClaims) if err != nil { - a.Ctx.StopWithError(iris.StatusInternalServerError, errorx.RejectedOperation.Wrap(err, "failed to invalidate token")) + msg := "failed to invalidate token" + shared.GetLogger().Error(msg, zap.Error(err), zap.String("token", hex.EncodeToString(verifiedToken.Token))) + a.Ctx.StopWithError(iris.StatusInternalServerError, errorx.RejectedOperation.Wrap(err, msg)) return } if err := db.Get().Delete(&challenge).Error; err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New("failed to delete key challenge")) + msg := "failed to delete key challenge" + shared.GetLogger().Error(msg, zap.Error(err), zap.Any("key_challenge", challenge)) + a.Ctx.StopWithError(iris.StatusBadRequest, errorx.RejectedOperation.New(msg)) return } // Return the JWT token to the client. err = a.Ctx.JSON(&LoginResponse{Token: token}) if err != nil { - panic(fmt.Errorf("Error with login attempt: %s \n", err)) + shared.GetLogger().Error("failed to create response", zap.Error(err)) } } @@ -273,6 +304,7 @@ func (a *AuthController) PostLogout() { // Read the logout request from the client. if err := a.Ctx.ReadJSON(&r); err != nil { + shared.GetLogger().Debug("failed to parse request", zap.Error(err)) a.Ctx.StopWithError(iris.StatusBadRequest, err) return } @@ -280,13 +312,18 @@ func (a *AuthController) PostLogout() { // Verify the provided token. claims, err := jwt.Verify(jwt.HS256, sharedKey, []byte(r.Token), blocklist) if err != nil { - a.Ctx.StopWithError(iris.StatusBadRequest, errors.New("invalid token")) + msg := "invalid token" + shared.GetLogger().Debug(msg, zap.Error(err)) + a.Ctx.StopWithError(iris.StatusBadRequest, errors.New(msg)) return } err = blocklist.InvalidateToken(claims.Token, claims.StandardClaims) if err != nil { - panic(fmt.Errorf("Error with logout: %s \n", err)) + msg := "failed to invalidate token" + shared.GetLogger().Error(msg, zap.Error(err), zap.String("token", hex.EncodeToString(claims.Token))) + a.Ctx.StopWithError(iris.StatusBadRequest, errors.New(msg)) + return } // Return a success response to the client. diff --git a/controller/files.go b/controller/files.go index 9246065..b1da413 100644 --- a/controller/files.go +++ b/controller/files.go @@ -4,7 +4,9 @@ import ( "errors" "git.lumeweb.com/LumeWeb/portal/cid" "git.lumeweb.com/LumeWeb/portal/service/files" + "git.lumeweb.com/LumeWeb/portal/shared" "github.com/kataras/iris/v12" + "go.uber.org/zap" "io" ) @@ -20,22 +22,29 @@ func (f *FilesController) PostUpload() { file, meta, err := f.Ctx.FormFile("file") if internalErrorCustom(ctx, err, errors.New("invalid file data")) { + shared.GetLogger().Debug("invalid file data", zap.Error(err)) return } upload, err := files.Upload(file, meta.Size) if internalError(ctx, err) { + shared.GetLogger().Debug("failed uploading file", zap.Error(err)) return } cidString, err := cid.EncodeString(upload.Hash, uint64(meta.Size)) if internalError(ctx, err) { + shared.GetLogger().Debug("failed creating cid", zap.Error(err)) return } - _ = ctx.JSON(&UploadResponse{Cid: cidString}) + err = ctx.JSON(&UploadResponse{Cid: cidString}) + + if err != nil { + shared.GetLogger().Error("failed to create response", zap.Error(err)) + } } func (f *FilesController) GetDownloadBy(cidString string) { @@ -43,18 +52,15 @@ func (f *FilesController) GetDownloadBy(cidString string) { _, err := cid.Valid(cidString) if sendError(ctx, err, iris.StatusBadRequest) { + shared.GetLogger().Debug("invalid cid", zap.Error(err)) return } cidObject, _ := cid.Decode(cidString) hashHex := cidObject.StringHash() - - if internalError(ctx, err) { - return - } - download, err := files.Download(hashHex) if internalError(ctx, err) { + shared.GetLogger().Debug("failed fetching file", zap.Error(err)) return } @@ -63,7 +69,9 @@ func (f *FilesController) GetDownloadBy(cidString string) { _ = download.(io.Closer).Close() return err }) - internalError(ctx, err) + if internalError(ctx, err) { + shared.GetLogger().Debug("failed streaming file", zap.Error(err)) + } } func sendErrorCustom(ctx iris.Context, err error, customError error, irisError int) bool { diff --git a/main.go b/main.go index 21a2814..c494939 100644 --- a/main.go +++ b/main.go @@ -15,6 +15,7 @@ import ( "github.com/iris-contrib/swagger/swaggerFiles" "github.com/kataras/iris/v12" "github.com/kataras/iris/v12/mvc" + "go.uber.org/zap" "log" "net/http" ) @@ -108,7 +109,7 @@ func main() { }) if err != nil { - log.Fatal(err) + shared.GetLogger().Error("Failed starting webserver proof", zap.Error(err)) } renterd.ShutdownComplete() diff --git a/service/files/files.go b/service/files/files.go index 689f555..bd7b018 100644 --- a/service/files/files.go +++ b/service/files/files.go @@ -11,7 +11,9 @@ import ( "git.lumeweb.com/LumeWeb/portal/renterd" "git.lumeweb.com/LumeWeb/portal/shared" "github.com/go-resty/resty/v2" + "go.uber.org/zap" "io" + "strings" ) var client *resty.Client @@ -29,6 +31,7 @@ func Upload(r io.ReadSeeker, size int64) (model.Upload, error) { tree, hashBytes, err := bao.ComputeTree(r, size) if err != nil { + shared.GetLogger().Error("Failed to hash file", zap.Error(err)) return upload, err } @@ -44,6 +47,7 @@ func Upload(r io.ReadSeeker, size int64) (model.Upload, error) { if (result.Error != nil && result.Error.Error() != "record not found") || result.RowsAffected > 0 { err := result.Row().Scan(&upload) if err != nil { + shared.GetLogger().Error("Failed to query uploads table", zap.Error(err)) return upload, err } } @@ -51,6 +55,7 @@ func Upload(r io.ReadSeeker, size int64) (model.Upload, error) { objectExistsResult, err := client.R().Get(fmt.Sprintf("/worker/objects/%s", hashHex)) if err != nil { + shared.GetLogger().Error("Failed query object", zap.Error(err)) return upload, err } @@ -68,13 +73,15 @@ func Upload(r io.ReadSeeker, size int64) (model.Upload, error) { ret, err := client.R().SetBody(r).Put(fmt.Sprintf("/worker/objects/%s", hashHex)) if ret.StatusCode() != 200 { - err = errors.New(string(ret.Body())) + shared.GetLogger().Error("Failed uploading object", zap.String("error", ret.String())) + err = errors.New(ret.String()) return upload, err } ret, err = client.R().SetBody(tree).Put(fmt.Sprintf("/worker/objects/%s.obao", hashHex)) if ret.StatusCode() != 200 { - err = errors.New(string(ret.Body())) + shared.GetLogger().Error("Failed uploading proof", zap.String("error", ret.String())) + err = errors.New(ret.String()) return upload, err } @@ -83,6 +90,7 @@ func Upload(r io.ReadSeeker, size int64) (model.Upload, error) { } if err = db.Get().Create(&upload).Error; err != nil { + shared.GetLogger().Error("Failed adding upload to db", zap.Error(err)) return upload, err } @@ -95,6 +103,7 @@ func Download(hash string) (io.Reader, error) { if uploadItem.Err() == nil { fetch, err := client.R().SetDoNotParseResponse(true).Get(fmt.Sprintf("/worker/objects/%s", hash)) if err != nil { + shared.GetLogger().Error("Failed downloading object", zap.Error(err)) return nil, err } @@ -103,21 +112,25 @@ func Download(hash string) (io.Reader, error) { var tusData model.Tus err := tusItem.Scan(&tusData) if err != nil { + shared.GetLogger().Error("Failed querying upload from db", zap.Error(err)) return nil, err } upload, err := shared.GetTusStore().GetUpload(context.Background(), tusData.Id) if err != nil { + shared.GetLogger().Error("Failed querying tus upload", zap.Error(err)) return nil, err } reader, err := upload.GetReader(context.Background()) if err != nil { + shared.GetLogger().Error("Failed reading tus upload", zap.Error(err)) return nil, err } return reader, nil } else { + shared.GetLogger().Error("invalid file") return nil, errors.New("invalid file") } } diff --git a/tus/tus.go b/tus/tus.go index eaca1f5..961947b 100644 --- a/tus/tus.go +++ b/tus/tus.go @@ -14,6 +14,7 @@ import ( "github.com/tus/tusd/pkg/filestore" tusd "github.com/tus/tusd/pkg/handler" "github.com/tus/tusd/pkg/memorylocker" + "go.uber.org/zap" "io" "log" ) @@ -43,7 +44,9 @@ func Init() *tusd.Handler { hash := hook.Upload.MetaData[HASH_META_HEADER] if len(hash) == 0 { - return errors.New("missing blake3-hash metadata") + msg := "missing blake3-hash metadata" + shared.GetLogger().Debug(msg) + return errors.New(msg) } var upload model.Upload @@ -51,18 +54,21 @@ func Init() *tusd.Handler { if (result.Error != nil && result.Error.Error() != "record not found") || result.RowsAffected > 0 { hashBytes, err := hex.DecodeString(hash) if err != nil { + shared.GetLogger().Debug("invalid hash", zap.Error(err)) return err } cidString, err := cid.Encode(hashBytes, uint64(hook.Upload.Size)) if err != nil { + shared.GetLogger().Debug("failed to create cid", zap.Error(err)) return err } resp, err := json.Marshal(UploadResponse{Cid: cidString}) if err != nil { + shared.GetLogger().Error("failed to create response", zap.Error(err)) return err } @@ -78,16 +84,19 @@ func Init() *tusd.Handler { } if err := db.Get().Create(tusEntry).Error; err != nil { + shared.GetLogger().Error("failed to create tus entry", zap.Error(err)) return err } if err := shared.GetTusQueue().QueueTask(func(ctx context.Context) error { upload, err := store.GetUpload(nil, hook.Upload.ID) if err != nil { + shared.GetLogger().Error("failed to query tus upload", zap.Error(err)) return err } return tusWorker(&upload) }); err != nil { + shared.GetLogger().Error("failed to queue tus upload", zap.Error(err)) return err } @@ -116,6 +125,7 @@ func tusStartup() { if err := tusQueue.QueueTask(func(ctx context.Context) error { upload, err := store.GetUpload(nil, item.UploadID) if err != nil { + shared.GetLogger().Error("failed to query tus upload", zap.Error(err)) return err } return tusWorker(&upload) @@ -126,20 +136,19 @@ func tusStartup() { } func tusWorker(upload *tusd.Upload) error { - info, err := (*upload).GetInfo(nil) + info, err := (*upload).GetInfo(context.Background()) if err != nil { - log.Print(err) + shared.GetLogger().Error("failed to query tus upload metadata", zap.Error(err)) return err } - file, err := (*upload).GetReader(nil) + file, err := (*upload).GetReader(context.Background()) if err != nil { - log.Print(err) + shared.GetLogger().Error("failed reading upload", zap.Error(err)) return err } _, err = files.Upload(file.(io.ReadSeeker), info.Size) if err != nil { - log.Print(err) err1 := terminateUpload(*upload) if err1 != nil { return err1 @@ -153,7 +162,7 @@ func tusWorker(upload *tusd.Upload) error { ret := db.Get().Where(&model.Tus{Hash: hash}).First(&tusUpload) if ret.Error != nil && ret.Error.Error() != "record not found" { - log.Print(ret.Error) + shared.GetLogger().Error("failed fetching tus entry", zap.Error(err)) err1 := terminateUpload(*upload) if err1 != nil { return err1 @@ -161,7 +170,7 @@ func tusWorker(upload *tusd.Upload) error { return err } - ret = db.Get().Delete(&tusUpload) + _ = db.Get().Delete(&tusUpload) err = terminateUpload(*upload) @@ -176,7 +185,7 @@ func terminateUpload(upload tusd.Upload) error { err := shared.GetTusComposer().Terminater.AsTerminatableUpload(upload).Terminate(context.Background()) if err != nil { - log.Print(err) + shared.GetLogger().Error("failed deleting tus upload", zap.Error(err)) return err }