Merge branch 'main' into dashboard

cmd/integration-test-server/main.go

@@ -14,6 +14,8 @@ import (
 	"math"
 	"net/http"
 	"os"
+	"regexp"
+	"strings"
 	"time"
 
 	"github.com/crate-crypto/go-proto-danksharding-crypto/eth"
@@ -41,6 +43,7 @@ const (
 	uploadedDataFile = ".data"
 	shardFile0       = "../../es-data-it/shard-0.dat"
 	shardFile1       = "../../es-data-it/shard-1.dat"
+	logFile          = "../../es-node-it.log"
 )
 
 var (
@@ -175,7 +178,14 @@ func checkFinalState(state *node.NodeState) {
 			addErrorMessage("At lease one block should be mined successfully during the test.")
 		}
 		if shardState.SubmissionState.Failed > 0 {
-			addErrorMessage(fmt.Sprintf("%d submission failed during the test.", shardState.SubmissionState.Failed))
+			knownFailureCount := checkKnownFailure()
+			if knownFailureCount > 0 {
+				log.Warn("Check by design failure result", "failure", shardState.SubmissionState.Failed, "by design failure", knownFailureCount)
+			}
+			failureCount := shardState.SubmissionState.Failed - knownFailureCount
+			if failureCount > 0 {
+				addErrorMessage(fmt.Sprintf("%d submission failed during the test.", failureCount))
+			}
 		}
 		log.Info("Final state", "id", state.Id, "shard", shardState.ShardId, "miner", shardState.Miner, "sync progress",
 			shardState.SyncState.SyncProgress, "fill progress", shardState.SyncState.FillEmptyProgress, "mining power",
@@ -278,6 +288,203 @@ func downloadBlobFromRPC(client *rpc.Client, kvIndex uint64, hash common.Hash) (
 	return result, nil
 }
 
+func checkKnownFailure() int {
+	count0, err := checkDiffNotMatchError()
+	if err != nil {
+		addErrorMessage(fmt.Sprintf("checkDiffNotMatchError fail: err, %s", err.Error()))
+	}
+	count1, err := checkInvalidSamplesError()
+	if err != nil {
+		addErrorMessage(fmt.Sprintf("checkInvalidSamplesError fail: err, %s", err.Error()))
+	}
+
+	return count0 + count1
+}
+
+func checkDiffNotMatchError() (int, error) {
+	// Description: "Mining info retrieved" -> "Failed to submit mined result"; shard and block equal which difficulty is not the same
+	// Sample:
+	// lvl=info msg="Mining info retrieved"                 shard=1 block=6,906,682 difficulty=13,006,115 lastMineTime=1,729,375,716 proofsSubmitted=2
+	// lvl=eror msg="Failed to submit mined result"         shard=1 block=6,906,682 difficulty=1,729,376,532 error="failed to estimate gas: execution reverted: StorageContract: diff not match"
+
+	file, err := os.OpenFile(logFile, os.O_RDONLY, 0755)
+	if err != nil {
+		return 0, err
+	}
+	defer file.Close()
+
+	fileScanner := bufio.NewScanner(file)
+	fileScanner.Split(bufio.ScanLines)
+
+	count := 0
+	difficultyMap := make(map[string]string)
+	for fileScanner.Scan() {
+		logText := fileScanner.Text()
+		if strings.Contains(logText, "Mining info retrieved") {
+			block, diff, err := fetchBlockAndDifficulty(logText)
+			if err != nil {
+				log.Error("fetchBlockAndDifficulty error", "log", logText, "error", err.Error())
+				continue
+			}
+			difficultyMap[block] = diff
+		} else if regexp.MustCompile(`Failed to submit mined result[\s\S]+diff not match`).MatchString(logText) {
+			block, diff, err := fetchBlockAndDifficulty(logText)
+			if err != nil {
+				log.Error("fetchBlockAndDifficulty error", "log", logText, "error", err.Error())
+				continue
+			}
+			if originalDiff, ok := difficultyMap[block]; ok && strings.Compare(diff, originalDiff) != 0 {
+				log.Warn("By design diff not match error", "block", block, "original difficulty", originalDiff, "latest difficulty", diff)
+				count++
+				continue
+			}
+		}
+	}
+
+	return count, nil
+}
+
+func checkInvalidSamplesError() (int, error) {
+	// description: 1. sample empty blob k, 2. download blob k, 3. submit mined result fail
+	// Sample:
+	// lvl=info msg="Get data hash"                         kvIndex=11742 hash=0x0000000000000000000000000000000000000000000000000000000000000000
+	// lvl=info msg="Downloaded and encoded"                blockNumber=4,225,672 kvIdx=11742
+	// lvl=info msg="Got storage proof"                     shard=1 block=6,906,682 kvIdx="[14613 11742]" sampleIdxsInKv="[1691 1859]"
+	// lvl=info msg="Mining result loop get result"         shard=1 block=6,906,682 nonce=539,139
+	// lvl=eror msg="Failed to submit mined result"         shard=1 block=6,906,682 error="failed to estimate gas: execution reverted: EthStorageContract2: invalid samples"
+
+	file, err := os.OpenFile(logFile, os.O_RDONLY, 0755)
+	if err != nil {
+		return 0, err
+	}
+	defer file.Close()
+
+	fileScanner := bufio.NewScanner(file)
+	fileScanner.Split(bufio.ScanLines)
+
+	count := 0
+	minedEmptyKVs := make(map[string]string)
+	legacyKVs := make(map[string]string)
+	for fileScanner.Scan() {
+		logText := fileScanner.Text()
+		if regexp.MustCompile(`Get data hash[\s\S]+hash=0x0000000000000000000000000000000000000000000000000000000000000000`).MatchString(logText) {
+			kvIdx := extractWithName(logText, `kvIndex=(?P<kvIdx>[\d]+)`, "kvIdx")
+			if kvIdx != "" {
+				minedEmptyKVs[kvIdx] = ""
+			}
+		} else if strings.Contains(logText, `Downloaded and encoded`) {
+			kvIdx := extractWithName(logText, `kvIdx=(?P<kvIdx>[\d]+)`, "kvIdx")
+			if kvIdx == "" {
+				continue
+			}
+			block, ok := minedEmptyKVs[kvIdx]
+			if !ok {
+				continue
+			}
+			legacyKVs[kvIdx] = block
+		} else if strings.Contains(logText, `Got storage proof`) {
+			block, kvIdxes, err := fetchMinedBlockAndKVIdx(logText)
+			if err != nil {
+				log.Error("checkInvalidSamplesError error", "log", logText, "error", err.Error())
+			}
+			for kvIdx := range minedEmptyKVs {
+				if !strings.Contains(kvIdxes, kvIdx) {
+					continue
+				}
+				minedEmptyKVs[kvIdx] = block
+				if _, ok := legacyKVs[kvIdx]; ok {
+					legacyKVs[kvIdx] = block
+				}
+			}
+		} else if regexp.MustCompile(`Failed to submit mined result[\s\S]+invalid samples`).MatchString(logText) {
+			for kvIdx, block := range legacyKVs {
+				if block != "" && strings.Contains(logText, block) {
+					log.Warn("By design error", "block", block, "kvIdx", kvIdx, "error", "invalid samples")
+					delete(legacyKVs, kvIdx)
+					count++
+					continue
+				}
+				delete(minedEmptyKVs, kvIdx)
+			}
+		} else if strings.Contains(logText, "Mining result loop get result") {
+			for kvIdx, block := range minedEmptyKVs {
+				if block != "" && strings.Contains(logText, block) {
+					delete(minedEmptyKVs, kvIdx)
+				}
+				continue
+			}
+		}
+	}
+
+	return count, nil
+}
+
+func fetchMinedBlockAndKVIdx(text string) (block string, kvIdx string, err error) {
+	patten := `block=(?P<block>[\d{1,3}(,\d{3})*]+)[\s]+kvIdx=\"\[(?P<kvIdx>\d+ \d+)\]\"`
+
+	results := extract(text, patten)
+	if len(results) == 2 {
+		for name, value := range results {
+			if strings.Compare(name, "block") == 0 {
+				block = value
+			} else if strings.Compare(name, "kvIdx") == 0 {
+				kvIdx = value
+			}
+		}
+	}
+
+	if block == "" || kvIdx == "" {
+		err = errors.New(fmt.Sprintf("extract mined block and nonce fail, %s, error: wrong log format", patten))
+	}
+
+	return
+}
+
+func fetchBlockAndDifficulty(text string) (string, string, error) {
+	patten := `shard=(?P<shard>[\d])[\s]+block=(?P<block>[\d{1,3}(,\d{3})*]+)[\s]+difficulty=(?P<difficulty>[\d{1,3}(,\d{3})*]+)`
+	shard, block, diff := "", "", ""
+
+	results := extract(text, patten)
+	if len(results) == 3 {
+		for name, value := range results {
+			if strings.Compare(name, "shard") == 0 {
+				shard = value
+			} else if strings.Compare(name, "block") == 0 {
+				block = value
+			} else if strings.Compare(name, "difficulty") == 0 {
+				diff = value
+			}
+		}
+	}
+
+	if shard == "" || block == "" || diff == "" {
+		return "", "", errors.New(fmt.Sprintf("extract block and difficulty fail, patten: %s; error: wrong log format.", patten))
+	}
+
+	return fmt.Sprintf("%s-%s", shard, block), diff, nil
+}
+
+func extractWithName(text, patten, name string) string {
+	results := extract(text, patten)
+	return results[name]
+}
+
+func extract(text, patten string) map[string]string {
+	results := make(map[string]string)
+	re := regexp.MustCompile(patten)
+
+	matches := re.FindStringSubmatch(text)
+	if matches != nil {
+		for i, name := range re.SubexpNames() {
+			if i != 0 && name != "" {
+				results[name] = matches[i]
+			}
+		}
+	}
+
+	return results
+}
+
 func addErrorMessage(errMessage string) {
 	log.Warn("Add error message", "msg", errMessage)
 	errorMessages = append(errorMessages, errMessage+"\n")

ethstorage/miner/worker.go

@@ -9,6 +9,7 @@ import (
 	"errors"
 	"fmt"
 	"math/big"
+	"strings"
 	"sync"
 	"sync/atomic"
 	"time"
@@ -255,7 +256,7 @@ func (w *worker) newWorkLoop() {
 			// 1) a mining tx is already submitted; or
 			// 2) if the last mining time is too close (the reward is not enough).
 			for shardIdx, task := range w.shardTaskMap {
-				reqDiff, err := w.updateDifficulty(shardIdx, block.Time)
+				reqDiff, err := w.updateDifficulty(shardIdx, block)
 				if err != nil {
 					continue
 				}
@@ -311,7 +312,7 @@ func (w *worker) assignTasks(task task, block eth.L1BlockRef, reqDiff *big.Int)
 	w.lg.Debug("Mining tasks assigned", "miner", task.miner, "shard", task.shardIdx, "threads", w.config.ThreadsPerShard, "block", block.Number, "nonces", w.config.NonceLimit)
 }
 
-func (w *worker) updateDifficulty(shardIdx, blockTime uint64) (*big.Int, error) {
+func (w *worker) updateDifficulty(shardIdx uint64, block eth.L1BlockRef) (*big.Int, error) {
 	info, err := w.l1API.GetMiningInfo(
 		context.Background(),
 		w.storageMgr.ContractAddress(),
@@ -321,13 +322,13 @@ func (w *worker) updateDifficulty(shardIdx, blockTime uint64) (*big.Int, error)
 		w.lg.Warn("Failed to get es mining info", "error", err.Error())
 		return nil, err
 	}
-	w.lg.Info("Mining info retrieved", "shard", shardIdx, "lastMineTime", info.LastMineTime, "difficulty", info.Difficulty, "proofsSubmitted", info.BlockMined)
+	w.lg.Info("Mining info retrieved", "shard", shardIdx, "block", block.Number, "difficulty", info.Difficulty, "lastMineTime", info.LastMineTime, "proofsSubmitted", info.BlockMined)
 
-	if blockTime <= info.LastMineTime {
+	if block.Time <= info.LastMineTime {
 		return nil, errors.New("minedTs too small")
 	}
 	reqDiff := new(big.Int).Div(maxUint256, expectedDiff(
-		blockTime-info.LastMineTime,
+		block.Time-info.LastMineTime,
 		info.Difficulty,
 		w.config.Cutoff,
 		w.config.DiffAdjDivisor,
@@ -411,7 +412,24 @@ func (w *worker) resultLoop() {
 					} else {
 						s.Failed++
 						errorCache = append(errorCache, miningError{result.startShardId, result.blockNumber, err})
-						w.lg.Error("Failed to submit mined result", "shard", result.startShardId, "block", result.blockNumber, "error", err.Error())
+						var diff *big.Int
+						if strings.Contains(err.Error(), "diff not match") {
+							info, err := w.l1API.GetMiningInfo(
+								context.Background(),
+								w.storageMgr.ContractAddress(),
+								result.startShardId,
+							)
+							if err != nil {
+								w.lg.Warn("Failed to get es mining info", "error", err.Error())
+							} else {
+								diff = info.Difficulty
+							}
+						}
+						if diff != nil {
+							w.lg.Error("Failed to submit mined result", "shard", result.startShardId, "block", result.blockNumber, "difficulty", diff, "error", err.Error())
+						} else {
+							w.lg.Error("Failed to submit mined result", "shard", result.startShardId, "block", result.blockNumber, "error", err.Error())
+						}
 					}
 				} else {
 					s.Succeeded++