Skip to content

Commit fd25924

Browse files
cnlangzicnlangzi
authored
Fix/challenge log (#400)
* fix(challenge): improved logging for challenge * fix(challenge): improved logging and fixed VerifyMerklePath * fix(gomod): fixed gosdk package for ci jobs * fix(gomod): fixed gosdk package
1 parent 97771a8 commit fd25924

File tree

8 files changed

+76
-62
lines changed

8 files changed

+76
-62
lines changed

‎code/go/0chain.net/blobbercore/allocation/newfilechange.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,9 +22,9 @@ type NewFileChange struct {
2222
//client side:
2323
Path string `json:"filepath" validation:"required"`
2424
//client side:
25-
ActualHash string `json:"actual_hash,omitempty" validation:"required"`
25+
ActualHash string `json:"actual_hash,omitempty" `
2626
//client side:
27-
ActualSize int64 `json:"actual_size,omitempty" validation:"required"`
27+
ActualSize int64 `json:"actual_size,omitempty"`
2828
//client side:
2929
ActualThumbnailSize int64 `json:"actual_thumb_size"`
3030
//client side:

‎code/go/0chain.net/blobbercore/challenge/challenge.go‎

Lines changed: 21 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"github.com/0chain/blobber/code/go/0chain.net/blobbercore/config"
1010
"github.com/0chain/blobber/code/go/0chain.net/blobbercore/datastore"
1111
"github.com/0chain/blobber/code/go/0chain.net/core/chain"
12+
"github.com/0chain/blobber/code/go/0chain.net/core/common"
1213
"github.com/0chain/blobber/code/go/0chain.net/core/lock"
1314
"github.com/0chain/blobber/code/go/0chain.net/core/node"
1415
"github.com/0chain/blobber/code/go/0chain.net/core/transaction"
@@ -40,7 +41,7 @@ func syncOpenChallenges(ctx context.Context) {
4041
retBytes, err := transaction.MakeSCRestAPICall(transaction.STORAGE_CONTRACT_ADDRESS, "/openchallenges", params, chain.GetServerChain())
4142

4243
if err != nil {
43-
logging.Logger.Error("Error getting the open challenges from the blockchain", zap.Error(err))
44+
logging.Logger.Error("[challenge]open: ", zap.Error(err))
4445
} else {
4546

4647
bytesReader := bytes.NewBuffer(retBytes)
@@ -50,11 +51,11 @@ func syncOpenChallenges(ctx context.Context) {
5051
errd := d.Decode(&blobberChallenges)
5152

5253
if errd != nil {
53-
logging.Logger.Error("Error in unmarshal of the sharder response", zap.Error(errd))
54+
logging.Logger.Error("[challenge]json: ", zap.Error(errd))
5455
} else {
5556
for _, challengeObj := range blobberChallenges.Challenges {
5657
if challengeObj == nil || len(challengeObj.ChallengeID) == 0 {
57-
logging.Logger.Info("No challenge entity from the challenge map")
58+
logging.Logger.Info("[challenge]open: No challenge entity from the challenge map")
5859
continue
5960
}
6061

@@ -69,7 +70,7 @@ func syncOpenChallenges(ctx context.Context) {
6970

7071
if err != nil {
7172
if !errors.Is(err, gorm.ErrRecordNotFound) {
72-
logging.Logger.Info("Error in load challenge entity from database ", zap.Error(err))
73+
logging.Logger.Error("[challenge]db: ", zap.Error(err))
7374
continue
7475
}
7576
}
@@ -78,13 +79,16 @@ func syncOpenChallenges(ctx context.Context) {
7879
isNextChallengeOnChain := latestChallenge == nil || latestChallenge.ChallengeID == challengeObj.PrevChallengeID
7980

8081
if isFirstChallengeInDatabase || isNextChallengeOnChain {
81-
logging.Logger.Info("Adding new challenge found from blockchain", zap.String("challenge", challengeObj.ChallengeID))
82+
logging.Logger.Info("[challenge]add: ", zap.String("challenge_id", challengeObj.ChallengeID))
8283
challengeObj.Status = Accepted
84+
challengeObj.CreatedAt = common.ToTime(challengeObj.Created)
85+
challengeObj.UpdatedAt = challengeObj.CreatedAt
86+
8387
if err := challengeObj.Save(tx); err != nil {
84-
logging.Logger.Error("ChallengeEntity_Save", zap.String("challenge_id", challengeObj.ChallengeID), zap.Error(err))
88+
logging.Logger.Error("[challenge]db: ", zap.String("challenge_id", challengeObj.ChallengeID), zap.Error(err))
8589
}
8690
} else {
87-
logging.Logger.Error("Challenge chain is not valid")
91+
logging.Logger.Error("[challenge]Challenge chain is not valid")
8892
}
8993

9094
}
@@ -110,26 +114,29 @@ func processAccepted(ctx context.Context) {
110114
if len(openchallenges) > 0 {
111115
swg := sizedwaitgroup.New(config.Configuration.ChallengeResolveNumWorkers)
112116
for _, openchallenge := range openchallenges {
113-
logging.Logger.Info("Processing the challenge", zap.Any("challenge_id", openchallenge.ChallengeID), zap.Any("openchallenge", openchallenge))
117+
logging.Logger.Info("[challenge]process: ", zap.String("challenge_id", openchallenge.ChallengeID))
114118
err := openchallenge.UnmarshalFields()
115119
if err != nil {
116-
logging.Logger.Error("Error unmarshaling challenge entity.", zap.Error(err))
120+
logging.Logger.Error("[challenge]json: ", zap.Error(err))
117121
continue
118122
}
119123
swg.Add()
120124
go func(redeemCtx context.Context, challengeEntity *ChallengeEntity) {
125+
defer swg.Done()
121126
redeemCtx = datastore.GetStore().CreateTransaction(redeemCtx)
122127
defer redeemCtx.Done()
123128
err := loadValidationTickets(redeemCtx, challengeEntity)
124129
if err != nil {
125-
logging.Logger.Error("Getting validation tickets failed", zap.Any("challenge_id", challengeEntity.ChallengeID), zap.Error(err))
130+
logging.Logger.Error("[challenge]validate: ", zap.Any("challenge_id", challengeEntity.ChallengeID), zap.Error(err))
131+
return
126132
}
127133
db := datastore.GetStore().GetTransaction(redeemCtx)
128134
err = db.Commit().Error
129135
if err != nil {
130-
logging.Logger.Error("Error commiting the readmarker redeem", zap.Error(err))
136+
logging.Logger.Error("[challenge]db: ", zap.Any("challenge_id", challengeEntity.ChallengeID), zap.Error(err))
137+
return
131138
}
132-
swg.Done()
139+
133140
}(ctx, openchallenge)
134141
}
135142
swg.Wait()
@@ -145,13 +152,13 @@ func loadValidationTickets(ctx context.Context, challengeObj *ChallengeEntity) e
145152

146153
defer func() {
147154
if r := recover(); r != nil {
148-
logging.Logger.Error("[recover] LoadValidationTickets", zap.Any("err", r))
155+
logging.Logger.Error("[recover]LoadValidationTickets", zap.Any("err", r))
149156
}
150157
}()
151158

152159
err := challengeObj.LoadValidationTickets(ctx)
153160
if err != nil {
154-
logging.Logger.Error("Error getting the validation tickets", zap.Error(err), zap.String("challenge_id", challengeObj.ChallengeID))
161+
logging.Logger.Error("[challenge]load: ", zap.String("challenge_id", challengeObj.ChallengeID), zap.Error(err))
155162
}
156163

157164
return err

‎code/go/0chain.net/blobbercore/challenge/entity.go‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import (
44
"context"
55
"encoding/json"
66
"fmt"
7+
"time"
78

89
"github.com/0chain/blobber/code/go/0chain.net/blobbercore/datastore"
910
"github.com/0chain/blobber/code/go/0chain.net/blobbercore/reference"
@@ -76,6 +77,9 @@ type ChallengeEntity struct {
7677
ObjectPathString datatypes.JSON `json:"-" gorm:"column:object_path"`
7778
ObjectPath *reference.ObjectPath `json:"object_path" gorm:"-"`
7879
Created common.Timestamp `json:"created" gorm:"-"`
80+
81+
CreatedAt time.Time `gorm:"created_at"`
82+
UpdatedAt time.Time `gorm:"updated_at"`
7983
}
8084

8185
func (ChallengeEntity) TableName() string {

‎code/go/0chain.net/blobbercore/challenge/protocol.go‎

Lines changed: 31 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -63,19 +63,23 @@ func (cr *ChallengeEntity) SubmitChallengeToBC(ctx context.Context) (*transactio
6363

6464
func (cr *ChallengeEntity) ErrorChallenge(ctx context.Context, err error) {
6565
cr.StatusMessage = err.Error()
66+
cr.UpdatedAt = time.Now().UTC()
67+
6668
if err := cr.Save(ctx); err != nil {
67-
Logger.Error("ChallengeEntity_Save", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
69+
Logger.Error("[challenge]db: ", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
6870
}
6971
}
7072

7173
// LoadValidationTickets load validation tickets
7274
func (cr *ChallengeEntity) LoadValidationTickets(ctx context.Context) error {
7375
if len(cr.Validators) == 0 {
74-
cr.StatusMessage = "No validators assigned to the challange"
76+
cr.StatusMessage = "No validators assigned to the challenge"
77+
cr.UpdatedAt = time.Now().UTC()
78+
7579
if err := cr.Save(ctx); err != nil {
76-
Logger.Error("ChallengeEntity_Save", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
80+
Logger.Error("[challenge]db: ", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
7781
}
78-
return common.NewError("no_validators", "No validators assigned to the challange")
82+
return common.NewError("no_validators", "No validators assigned to the challenge")
7983
}
8084

8185
allocationObj, err := allocation.GetAllocationByID(ctx, cr.AllocationID)
@@ -97,16 +101,19 @@ func (cr *ChallengeEntity) LoadValidationTickets(ctx context.Context) error {
97101
r := rand.New(rand.NewSource(cr.RandomNumber))
98102
blockNum = r.Int63n(rootRef.NumBlocks)
99103
blockNum = blockNum + 1
104+
cr.BlockNum = blockNum
100105
} else {
101-
Logger.Error("Got a challenge for a blank allocation")
106+
err = common.NewError("allocation_is_blank", "Got a challenge for a blank allocation")
107+
cr.ErrorChallenge(ctx, err)
108+
return err
102109
}
103110

104-
cr.BlockNum = blockNum
105111
if err != nil {
106112
cr.ErrorChallenge(ctx, err)
107113
return err
108114
}
109-
Logger.Info("blockNum for challenge", zap.Any("rootRef.NumBlocks", rootRef.NumBlocks), zap.Any("blockNum", blockNum), zap.Any("challenge_id", cr.ChallengeID), zap.Any("random_seed", cr.RandomNumber))
115+
116+
Logger.Info("[challenge]rand: ", zap.Any("rootRef.NumBlocks", rootRef.NumBlocks), zap.Any("blockNum", blockNum), zap.Any("challenge_id", cr.ChallengeID), zap.Any("random_seed", cr.RandomNumber))
110117
objectPath, err := reference.GetObjectPath(ctx, cr.AllocationID, blockNum)
111118
if err != nil {
112119
cr.ErrorChallenge(ctx, err)
@@ -165,7 +172,7 @@ func (cr *ChallengeEntity) LoadValidationTickets(ctx context.Context) error {
165172

166173
postDataBytes, err := json.Marshal(postData)
167174
if err != nil {
168-
Logger.Error("Error in marshalling the post data for validation. " + err.Error())
175+
Logger.Error("[db]form: " + err.Error())
169176
cr.ErrorChallenge(ctx, err)
170177
return err
171178
}
@@ -185,23 +192,23 @@ func (cr *ChallengeEntity) LoadValidationTickets(ctx context.Context) error {
185192

186193
resp, err := util.SendPostRequest(url, postDataBytes, nil)
187194
if err != nil {
188-
Logger.Info("Got error from the validator.", zap.Any("error", err.Error()))
195+
Logger.Info("[challenge]post: ", zap.Any("error", err.Error()))
189196
delete(responses, validator.ID)
190197
cr.ValidationTickets[i] = nil
191198
continue
192199
}
193200
var validationTicket ValidationTicket
194201
err = json.Unmarshal(resp, &validationTicket)
195202
if err != nil {
196-
Logger.Info("Got error decoding from the validator response .", zap.Any("resp", string(resp)), zap.Any("error", err.Error()))
203+
Logger.Error("[challenge]resp: ", zap.String("validator", validator.ID), zap.Any("resp", string(resp)), zap.Any("error", err.Error()))
197204
delete(responses, validator.ID)
198205
cr.ValidationTickets[i] = nil
199206
continue
200207
}
201-
Logger.Info("Got response from the validator.", zap.Any("validator_response", validationTicket))
208+
Logger.Info("[challenge]resp: Got response from the validator.", zap.Any("validator_response", validationTicket))
202209
verified, err := validationTicket.VerifySign()
203210
if err != nil || !verified {
204-
Logger.Info("Validation ticket from validator could not be verified.")
211+
Logger.Error("[challenge]ticket: Validation ticket from validator could not be verified.", zap.String("validator", validator.ID))
205212
delete(responses, validator.ID)
206213
cr.ValidationTickets[i] = nil
207214
continue
@@ -219,22 +226,25 @@ func (cr *ChallengeEntity) LoadValidationTickets(ctx context.Context) error {
219226
if vt.Result {
220227
numSuccess++
221228
} else {
229+
Logger.Error("[challenge]ticket: "+vt.Message, zap.String("validator", vt.ValidatorID))
222230
numFailure++
223231
}
224232
numValidatorsResponded++
225233
}
226234
}
227235

228-
Logger.Info("validator response stats", zap.Any("challenge_id", cr.ChallengeID), zap.Any("validator_responses", responses))
236+
Logger.Info("[challenge]validator response stats", zap.Any("challenge_id", cr.ChallengeID), zap.Any("validator_responses", responses))
229237
if numSuccess > (len(cr.Validators)/2) || numFailure > (len(cr.Validators)/2) || numValidatorsResponded == len(cr.Validators) {
230238
if numSuccess > (len(cr.Validators) / 2) {
231239
cr.Result = ChallengeSuccess
232240
} else {
233241
cr.Result = ChallengeFailure
234-
//Logger.Error("Challenge failed by the validators", zap.Any("block_num", cr.BlockNum), zap.Any("object_path", objectPath), zap.Any("challenge", cr))
242+
243+
Logger.Error("[challenge]validate: ", zap.String("challenge_id", cr.ChallengeID), zap.Any("block_num", cr.BlockNum), zap.Any("object_path", objectPath))
235244
}
236245

237246
cr.Status = Processed
247+
cr.UpdatedAt = time.Now().UTC()
238248
} else {
239249
cr.ErrorChallenge(ctx, common.NewError("no_consensus_challenge", "No Consensus on the challenge result. Erroring out the challenge"))
240250
return common.NewError("no_consensus_challenge", "No Consensus on the challenge result. Erroring out the challenge")
@@ -247,19 +257,20 @@ func (cr *ChallengeEntity) CommitChallenge(ctx context.Context, verifyOnly bool)
247257

248258
if len(cr.LastCommitTxnIDs) > 0 {
249259
for _, lastTxn := range cr.LastCommitTxnIDs {
250-
Logger.Info("Verifying the transaction : " + lastTxn)
260+
Logger.Info("[challenge]commit: Verifying the transaction : " + lastTxn)
251261
t, err := transaction.VerifyTransaction(lastTxn, chain.GetServerChain())
252262
if err == nil {
253263
cr.Status = Committed
254264
cr.StatusMessage = t.TransactionOutput
255265
cr.CommitTxnID = t.Hash
266+
cr.UpdatedAt = time.Now().UTC()
256267
if err := cr.Save(ctx); err != nil {
257-
Logger.Error("ChallengeEntity_Save", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
268+
Logger.Error("[challenge]db: ", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
258269
}
259270
FileChallenged(ctx, cr.RefID, cr.Result, cr.CommitTxnID)
260271
return nil
261272
}
262-
Logger.Error("Error verifying the txn from BC."+lastTxn, zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
273+
Logger.Error("[challenge]trans: Error verifying the txn from BC."+lastTxn, zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
263274
}
264275
}
265276

@@ -272,14 +283,16 @@ func (cr *ChallengeEntity) CommitChallenge(ctx context.Context, verifyOnly bool)
272283
if t != nil {
273284
cr.CommitTxnID = t.Hash
274285
cr.LastCommitTxnIDs = append(cr.LastCommitTxnIDs, t.Hash)
286+
cr.UpdatedAt = time.Now().UTC()
275287
}
276288
cr.ErrorChallenge(ctx, err)
277-
Logger.Error("Error while submitting challenge to BC.", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
289+
Logger.Error("[challenge]submit: Error while submitting challenge to BC.", zap.String("challenge_id", cr.ChallengeID), zap.Error(err))
278290
} else {
279291
cr.Status = Committed
280292
cr.StatusMessage = t.TransactionOutput
281293
cr.CommitTxnID = t.Hash
282294
cr.LastCommitTxnIDs = append(cr.LastCommitTxnIDs, t.Hash)
295+
cr.UpdatedAt = time.Now().UTC()
283296
}
284297
err = cr.Save(ctx)
285298
FileChallenged(ctx, cr.RefID, cr.Result, cr.CommitTxnID)

‎code/go/0chain.net/blobbercore/challenge/worker.go‎

Lines changed: 5 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -15,40 +15,36 @@ func SetupWorkers(ctx context.Context) {
1515
}
1616

1717
func startCommitProcessed(ctx context.Context) {
18-
ticker := time.NewTicker(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second)
19-
defer ticker.Stop()
2018
for {
2119
select {
2220
case <-ctx.Done():
2321
return
24-
case <-ticker.C:
22+
case <-time.After(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second):
2523
commitProcessed(ctx)
2624
}
2725
}
2826
}
2927

3028
func startProcessAccepted(ctx context.Context) {
31-
ticker := time.NewTicker(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second)
32-
defer ticker.Stop()
29+
3330
for {
3431
select {
3532
case <-ctx.Done():
3633
return
37-
case <-ticker.C:
34+
case <-time.After(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second):
3835
processAccepted(ctx)
3936
}
4037
}
4138
}
4239

4340
// startSyncOpen
4441
func startSyncOpen(ctx context.Context) {
45-
ticker := time.NewTicker(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second)
46-
defer ticker.Stop()
42+
4743
for {
4844
select {
4945
case <-ctx.Done():
5046
return
51-
case <-ticker.C:
47+
case <-time.After(time.Duration(config.Configuration.ChallengeResolveFreq) * time.Second):
5248
syncOpenChallenges(ctx)
5349
}
5450
}

0 commit comments

Comments
 (0)