From f5837c99d1180331c3d47215a8cf4c93ee635ce6 Mon Sep 17 00:00:00 2001 From: Lz Date: Fri, 29 Jul 2022 11:29:41 +0800 Subject: [PATCH 1/4] fix(challenge): improved logging --- .../blobbercore/challenge/challenge.go | 40 ++++++++++++------- .../blobbercore/challenge/entity.go | 13 ++++++ 2 files changed, 39 insertions(+), 14 deletions(-) diff --git a/code/go/0chain.net/blobbercore/challenge/challenge.go b/code/go/0chain.net/blobbercore/challenge/challenge.go index 39bd7be93..47511ffb9 100644 --- a/code/go/0chain.net/blobbercore/challenge/challenge.go +++ b/code/go/0chain.net/blobbercore/challenge/challenge.go @@ -66,7 +66,7 @@ func syncOpenChallenges(ctx context.Context) { func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { defer func() { if r := recover(); r != nil { - logging.Logger.Error("[recover]challenge", zap.Any("err", r)) + logging.Logger.Error("[recover]add", zap.Any("err", r)) } }() @@ -78,7 +78,7 @@ func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { lastChallengeID, err := getLastChallengeID(db) if err != nil { - logging.Logger.Error("[challenge]db: ", zap.Error(err)) + logging.Logger.Error("[challenge]add: ", zap.Error(err)) return } @@ -98,7 +98,7 @@ func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { if err := db.Transaction(func(tx *gorm.DB) error { return nextChallenge.SaveWith(tx) }); err != nil { - logging.Logger.Error("[challenge]db: ", zap.String("challenge_id", nextChallenge.ChallengeID), zap.Error(err)) + logging.Logger.Error("[challenge]add: ", zap.String("challenge_id", nextChallenge.ChallengeID), zap.Error(err)) } } @@ -120,7 +120,12 @@ func processAccepted(ctx context.Context) { logging.Logger.Info("[challenge]process: ", zap.String("challenge_id", openchallenge.ChallengeID)) err := openchallenge.UnmarshalFields() if err != nil { - logging.Logger.Error("[challenge]json: ", zap.Error(err)) + logging.Logger.Error("[challenge]process: ", + zap.String("validators", string(openchallenge.ValidatorsString)), + zap.String("lastCommitTxnList", string(openchallenge.LastCommitTxnList)), + zap.String("validationTickets", string(openchallenge.ValidationTicketsString)), + zap.String("ObjectPath", string(openchallenge.ObjectPathString)), + zap.Error(err)) continue } swg.Add() @@ -144,10 +149,12 @@ func validateChallenge(swg *sizedwaitgroup.SizedWaitGroup, challengeObj *Challen } if err := db.Commit().Error; err != nil { - logging.Logger.Error("[challenge]db: ", zap.Any("challenge_id", challengeObj.ChallengeID), zap.Error(err)) + logging.Logger.Error("[challenge]validate: ", zap.Any("challenge_id", challengeObj.ChallengeID), zap.Error(err)) db.Rollback() return } + + logging.Logger.Info("[challenge]validate: ", zap.Any("challenge_id", challengeObj.ChallengeID)) } func commitProcessed(ctx context.Context) { @@ -179,9 +186,14 @@ func commitProcessed(ctx context.Context) { } func commitChallenge(openchallenge *ChallengeEntity) { - logging.Logger.Info("Attempting to commit challenge", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Any("openchallenge", openchallenge)) + logging.Logger.Info("[challenge]commit", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Any("openchallenge", openchallenge)) if err := openchallenge.UnmarshalFields(); err != nil { - logging.Logger.Error("ChallengeEntity_UnmarshalFields", zap.String("challenge_id", openchallenge.ChallengeID), zap.Error(err)) + logging.Logger.Error("[challenge]commit", zap.String("challenge_id", openchallenge.ChallengeID), + zap.String("validators", string(openchallenge.ValidatorsString)), + zap.String("lastCommitTxnList", string(openchallenge.LastCommitTxnList)), + zap.String("validationTickets", string(openchallenge.ValidationTicketsString)), + zap.String("ObjectPath", string(openchallenge.ObjectPathString)), + zap.Error(err)) } ctx := datastore.GetStore().CreateTransaction(context.TODO()) @@ -190,7 +202,7 @@ func commitChallenge(openchallenge *ChallengeEntity) { db := datastore.GetStore().GetTransaction(ctx) if err := openchallenge.CommitChallenge(ctx, false); err != nil { - logging.Logger.Error("Error committing to blockchain", + logging.Logger.Error("[challenge]commit", zap.Error(err), zap.String("challenge_id", openchallenge.ChallengeID)) db.Rollback() @@ -198,14 +210,14 @@ func commitChallenge(openchallenge *ChallengeEntity) { } if err := db.Commit(); err != nil { - logging.Logger.Info("Challenge was not committed", zap.Any("challenge_id", openchallenge.ChallengeID)) + logging.Logger.Warn("[challenge]commit", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Error(err)) db.Rollback() return } - if openchallenge.Status == Committed { - logging.Logger.Info("Challenge has been submitted to blockchain", - zap.Any("id", openchallenge.ChallengeID), - zap.String("txn", openchallenge.CommitTxnID)) - } + logging.Logger.Info("[challenge]commit", + zap.Any("challenge_id", openchallenge.ChallengeID), + zap.String("status", openchallenge.Status.String()), + zap.String("txn", openchallenge.CommitTxnID)) + } diff --git a/code/go/0chain.net/blobbercore/challenge/entity.go b/code/go/0chain.net/blobbercore/challenge/entity.go index 82599584b..dda23f1f6 100644 --- a/code/go/0chain.net/blobbercore/challenge/entity.go +++ b/code/go/0chain.net/blobbercore/challenge/entity.go @@ -29,6 +29,19 @@ const ( Committed ) +func (s ChallengeStatus) String() string { + switch s { + case Accepted: + return "Accepted" + case Processed: + return "Processed" + case Committed: + return "Committed" + default: + return fmt.Sprintf("%d", int(s)) + } +} + const ( ChallengeUnknown ChallengeResult = iota ChallengeSuccess From ff9216a4bf0b511471c45b9c5770a8fcea614695 Mon Sep 17 00:00:00 2001 From: Lz Date: Fri, 29 Jul 2022 17:03:13 +0800 Subject: [PATCH 2/4] fix(challenge): added created on logging for debugging --- .../blobbercore/challenge/challenge.go | 114 +++++++++++------- 1 file changed, 71 insertions(+), 43 deletions(-) diff --git a/code/go/0chain.net/blobbercore/challenge/challenge.go b/code/go/0chain.net/blobbercore/challenge/challenge.go index 47511ffb9..ffc045f75 100644 --- a/code/go/0chain.net/blobbercore/challenge/challenge.go +++ b/code/go/0chain.net/blobbercore/challenge/challenge.go @@ -63,7 +63,7 @@ func syncOpenChallenges(ctx context.Context) { } -func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { +func saveNewChallenge(c *ChallengeEntity, ctx context.Context) { defer func() { if r := recover(); r != nil { logging.Logger.Error("[recover]add", zap.Any("err", r)) @@ -71,7 +71,7 @@ func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { }() db := datastore.GetStore().GetDB() - if Exists(db, nextChallenge.ChallengeID) { + if Exists(db, c.ChallengeID) { return } @@ -82,7 +82,7 @@ func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { return } - isValid := nextChallenge.PrevChallengeID == "" || lastChallengeID == nextChallenge.PrevChallengeID + isValid := c.PrevChallengeID == "" || lastChallengeID == c.PrevChallengeID // it is not First and Next challenge if !isValid { @@ -90,15 +90,21 @@ func saveNewChallenge(nextChallenge *ChallengeEntity, ctx context.Context) { return } - logging.Logger.Info("[challenge]add: ", zap.String("challenge_id", nextChallenge.ChallengeID)) - nextChallenge.Status = Accepted - nextChallenge.CreatedAt = common.ToTime(nextChallenge.Created) - nextChallenge.UpdatedAt = nextChallenge.CreatedAt + c.Status = Accepted + c.CreatedAt = common.ToTime(c.Created) + c.UpdatedAt = c.CreatedAt + + logging.Logger.Info("[challenge]add: ", + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt)) if err := db.Transaction(func(tx *gorm.DB) error { - return nextChallenge.SaveWith(tx) + return c.SaveWith(tx) }); err != nil { - logging.Logger.Error("[challenge]add: ", zap.String("challenge_id", nextChallenge.ChallengeID), zap.Error(err)) + logging.Logger.Error("[challenge]add: ", + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Error(err)) } } @@ -112,49 +118,61 @@ func processAccepted(ctx context.Context) { }() db := datastore.GetStore().GetDB() - openchallenges := make([]*ChallengeEntity, 0) - db.Where(ChallengeEntity{Status: Accepted}).Find(&openchallenges) - if len(openchallenges) > 0 { + challenges := make([]*ChallengeEntity, 0) + db.Where(ChallengeEntity{Status: Accepted}).Find(&challenges) + if len(challenges) > 0 { swg := sizedwaitgroup.New(config.Configuration.ChallengeResolveNumWorkers) - for _, openchallenge := range openchallenges { - logging.Logger.Info("[challenge]process: ", zap.String("challenge_id", openchallenge.ChallengeID)) - err := openchallenge.UnmarshalFields() + for _, c := range challenges { + logging.Logger.Info("[challenge]process: ", + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt)) + err := c.UnmarshalFields() if err != nil { logging.Logger.Error("[challenge]process: ", - zap.String("validators", string(openchallenge.ValidatorsString)), - zap.String("lastCommitTxnList", string(openchallenge.LastCommitTxnList)), - zap.String("validationTickets", string(openchallenge.ValidationTicketsString)), - zap.String("ObjectPath", string(openchallenge.ObjectPathString)), + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.String("validators", string(c.ValidatorsString)), + zap.String("lastCommitTxnList", string(c.LastCommitTxnList)), + zap.String("validationTickets", string(c.ValidationTicketsString)), + zap.String("ObjectPath", string(c.ObjectPathString)), zap.Error(err)) continue } swg.Add() - go validateChallenge(&swg, openchallenge) + go validateChallenge(&swg, c) } swg.Wait() } } -func validateChallenge(swg *sizedwaitgroup.SizedWaitGroup, challengeObj *ChallengeEntity) { +func validateChallenge(swg *sizedwaitgroup.SizedWaitGroup, c *ChallengeEntity) { defer swg.Done() ctx := datastore.GetStore().CreateTransaction(context.TODO()) defer ctx.Done() db := datastore.GetStore().GetTransaction(ctx) - if err := challengeObj.LoadValidationTickets(ctx); err != nil { - logging.Logger.Error("[challenge]validate: ", zap.Any("challenge_id", challengeObj.ChallengeID), zap.Error(err)) + if err := c.LoadValidationTickets(ctx); err != nil { + logging.Logger.Error("[challenge]validate: ", + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Error(err)) db.Rollback() return } if err := db.Commit().Error; err != nil { - logging.Logger.Error("[challenge]validate: ", zap.Any("challenge_id", challengeObj.ChallengeID), zap.Error(err)) + logging.Logger.Error("[challenge]validate: ", + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Error(err)) db.Rollback() return } - logging.Logger.Info("[challenge]validate: ", zap.Any("challenge_id", challengeObj.ChallengeID)) + logging.Logger.Info("[challenge]validate: ", + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt)) } func commitProcessed(ctx context.Context) { @@ -173,8 +191,8 @@ func commitProcessed(ctx context.Context) { if len(challenges) > 0 { swg := sizedwaitgroup.New(config.Configuration.ChallengeResolveNumWorkers) - for _, challenge := range challenges { - c := challenge + for _, c := range challenges { + c := c swg.Add() go func() { defer swg.Done() @@ -185,14 +203,19 @@ func commitProcessed(ctx context.Context) { } } -func commitChallenge(openchallenge *ChallengeEntity) { - logging.Logger.Info("[challenge]commit", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Any("openchallenge", openchallenge)) - if err := openchallenge.UnmarshalFields(); err != nil { - logging.Logger.Error("[challenge]commit", zap.String("challenge_id", openchallenge.ChallengeID), - zap.String("validators", string(openchallenge.ValidatorsString)), - zap.String("lastCommitTxnList", string(openchallenge.LastCommitTxnList)), - zap.String("validationTickets", string(openchallenge.ValidationTicketsString)), - zap.String("ObjectPath", string(openchallenge.ObjectPathString)), +func commitChallenge(c *ChallengeEntity) { + logging.Logger.Info("[challenge]commit", + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Any("openchallenge", c)) + if err := c.UnmarshalFields(); err != nil { + logging.Logger.Error("[challenge]commit", + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.String("validators", string(c.ValidatorsString)), + zap.String("lastCommitTxnList", string(c.LastCommitTxnList)), + zap.String("validationTickets", string(c.ValidationTicketsString)), + zap.String("ObjectPath", string(c.ObjectPathString)), zap.Error(err)) } @@ -201,23 +224,28 @@ func commitChallenge(openchallenge *ChallengeEntity) { db := datastore.GetStore().GetTransaction(ctx) - if err := openchallenge.CommitChallenge(ctx, false); err != nil { + if err := c.CommitChallenge(ctx, false); err != nil { logging.Logger.Error("[challenge]commit", - zap.Error(err), - zap.String("challenge_id", openchallenge.ChallengeID)) + zap.String("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Error(err)) db.Rollback() return } - if err := db.Commit(); err != nil { - logging.Logger.Warn("[challenge]commit", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Error(err)) + if err := db.Commit().Error; err != nil { + logging.Logger.Warn("[challenge]commit", + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.Error(err)) db.Rollback() return } logging.Logger.Info("[challenge]commit", - zap.Any("challenge_id", openchallenge.ChallengeID), - zap.String("status", openchallenge.Status.String()), - zap.String("txn", openchallenge.CommitTxnID)) + zap.Any("challenge_id", c.ChallengeID), + zap.Time("created", c.CreatedAt), + zap.String("status", c.Status.String()), + zap.String("txn", c.CommitTxnID)) } From e936cf723b4e1cd1ba439ac6307fc66d12518329 Mon Sep 17 00:00:00 2001 From: Lz Date: Fri, 29 Jul 2022 17:11:47 +0800 Subject: [PATCH 3/4] fix(challenge): improved logging for debugging --- code/go/0chain.net/blobbercore/challenge/challenge.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/code/go/0chain.net/blobbercore/challenge/challenge.go b/code/go/0chain.net/blobbercore/challenge/challenge.go index ffc045f75..377fbfe88 100644 --- a/code/go/0chain.net/blobbercore/challenge/challenge.go +++ b/code/go/0chain.net/blobbercore/challenge/challenge.go @@ -66,7 +66,7 @@ func syncOpenChallenges(ctx context.Context) { func saveNewChallenge(c *ChallengeEntity, ctx context.Context) { defer func() { if r := recover(); r != nil { - logging.Logger.Error("[recover]add", zap.Any("err", r)) + logging.Logger.Error("[recover]add_challenge", zap.Any("err", r)) } }() @@ -78,7 +78,7 @@ func saveNewChallenge(c *ChallengeEntity, ctx context.Context) { lastChallengeID, err := getLastChallengeID(db) if err != nil { - logging.Logger.Error("[challenge]add: ", zap.Error(err)) + logging.Logger.Error("[challenge]add(get_latest_challenge_id): ", zap.Error(err)) return } @@ -162,7 +162,7 @@ func validateChallenge(swg *sizedwaitgroup.SizedWaitGroup, c *ChallengeEntity) { } if err := db.Commit().Error; err != nil { - logging.Logger.Error("[challenge]validate: ", + logging.Logger.Error("[challenge]validate(Commit): ", zap.Any("challenge_id", c.ChallengeID), zap.Time("created", c.CreatedAt), zap.Error(err)) From d99a72e0730dd006acf076139382ad0309ed41ee Mon Sep 17 00:00:00 2001 From: Lz Date: Sun, 31 Jul 2022 07:24:46 +0800 Subject: [PATCH 4/4] fix(challenge): update closure in loop --- code/go/0chain.net/blobbercore/challenge/challenge.go | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/code/go/0chain.net/blobbercore/challenge/challenge.go b/code/go/0chain.net/blobbercore/challenge/challenge.go index 377fbfe88..cd44c9d79 100644 --- a/code/go/0chain.net/blobbercore/challenge/challenge.go +++ b/code/go/0chain.net/blobbercore/challenge/challenge.go @@ -191,13 +191,12 @@ func commitProcessed(ctx context.Context) { if len(challenges) > 0 { swg := sizedwaitgroup.New(config.Configuration.ChallengeResolveNumWorkers) - for _, c := range challenges { - c := c + for _, challenge := range challenges { swg.Add() - go func() { + go func(c *ChallengeEntity) { defer swg.Done() commitChallenge(c) - }() + }(challenge) } swg.Wait() }