tools: write block generator ledger output to a file (#5630)

ledger/lrukv.go

@@ -79,7 +79,7 @@ func (m *lruKV) read(key string) (data trackerdb.PersistedKVData, has bool) {
 func (m *lruKV) flushPendingWrites() {
 	pendingEntriesCount := len(m.pendingKVs)
 	if pendingEntriesCount >= m.pendingWritesWarnThreshold {
-		m.log.Warnf("lruKV: number of entries in pendingKVs(%d) exceed the warning threshold of %d", pendingEntriesCount, m.pendingWritesWarnThreshold)
+		m.log.Infof("lruKV: number of entries in pendingKVs(%d) exceed the warning threshold of %d", pendingEntriesCount, m.pendingWritesWarnThreshold)
 	}
 	for ; pendingEntriesCount > 0; pendingEntriesCount-- {
 		select {

ledger/lrukv_test.go

@@ -18,6 +18,7 @@ package ledger
 
 import (
 	"fmt"
+	"strings"
 	"testing"
 	"time"
 
@@ -162,8 +163,10 @@ type lruKVTestLogger struct {
 	warnMsgCount  int
 }
 
-func (cl *lruKVTestLogger) Warnf(s string, args ...interface{}) {
-	cl.warnMsgCount++
+func (cl *lruKVTestLogger) Infof(s string, args ...interface{}) {
+	if strings.Contains(s, "exceed the warning threshold of") {
+		cl.warnMsgCount++
+	}
 }
 
 func TestLRUKVPendingWritesWarning(t *testing.T) {

ledger/lruresources.go

@@ -103,7 +103,7 @@ func (m *lruResources) readAll(addr basics.Address) (ret []trackerdb.PersistedRe
 func (m *lruResources) flushPendingWrites() {
 	pendingEntriesCount := len(m.pendingResources)
 	if pendingEntriesCount >= m.pendingWritesWarnThreshold {
-		m.log.Warnf("lruResources: number of entries in pendingResources(%d) exceed the warning threshold of %d", pendingEntriesCount, m.pendingWritesWarnThreshold)
+		m.log.Infof("lruResources: number of entries in pendingResources(%d) exceed the warning threshold of %d", pendingEntriesCount, m.pendingWritesWarnThreshold)
 	}
 
 outer:

ledger/lruresources_test.go

@@ -18,6 +18,7 @@ package ledger
 
 import (
 	"encoding/binary"
+	"strings"
 	"testing"
 	"time"
 
@@ -180,8 +181,10 @@ type lruResourcesTestLogger struct {
 	warnMsgCount  int
 }
 
-func (cl *lruResourcesTestLogger) Warnf(s string, args ...interface{}) {
-	cl.warnMsgCount++
+func (cl *lruResourcesTestLogger) Infof(s string, args ...interface{}) {
+	if strings.Contains(s, "exceed the warning threshold of") {
+		cl.warnMsgCount++
+	}
 }
 
 func TestLRUResourcesPendingWritesWarning(t *testing.T) {

tools/block-generator/generator/generate.go

@@ -27,15 +27,15 @@ import (
 	"time"
 
 	cconfig "github.com/algorand/go-algorand/config"
-	"github.com/algorand/go-algorand/ledger/ledgercore"
-	"github.com/algorand/go-algorand/protocol"
-	"github.com/algorand/go-algorand/rpcs"
-
 	"github.com/algorand/go-algorand/crypto"
 	"github.com/algorand/go-algorand/daemon/algod/api/server/v2/generated/model"
 	"github.com/algorand/go-algorand/data/basics"
 	"github.com/algorand/go-algorand/data/bookkeeping"
 	txn "github.com/algorand/go-algorand/data/transactions"
+	"github.com/algorand/go-algorand/ledger/ledgercore"
+	"github.com/algorand/go-algorand/logging"
+	"github.com/algorand/go-algorand/protocol"
+	"github.com/algorand/go-algorand/rpcs"
 )
 
 // ---- templates ----
@@ -55,14 +55,19 @@ var clearSwap string
 // ---- constructors ----
 
 // MakeGenerator initializes the Generator object.
-func MakeGenerator(dbround uint64, bkGenesis bookkeeping.Genesis, config GenerationConfig, verbose bool) (Generator, error) {
+func MakeGenerator(log logging.Logger, dbround uint64, bkGenesis bookkeeping.Genesis, config GenerationConfig, verbose bool) (Generator, error) {
 	if err := config.validateWithDefaults(false); err != nil {
 		return nil, fmt.Errorf("invalid generator configuration: %w", err)
 	}
 
+	if log == nil {
+		log = logging.Base()
+	}
+
 	var proto protocol.ConsensusVersion = "future"
 	gen := &generator{
 		verbose:                   verbose,
+		log:                       log,
 		config:                    config,
 		protocol:                  proto,
 		params:                    cconfig.Consensus[proto],

tools/block-generator/generator/generate_test.go

@@ -24,15 +24,17 @@ import (
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/require"
+
 	"github.com/algorand/go-algorand/crypto"
 	"github.com/algorand/go-algorand/data/basics"
 	"github.com/algorand/go-algorand/data/bookkeeping"
 	"github.com/algorand/go-algorand/data/transactions"
 	"github.com/algorand/go-algorand/data/transactions/logic"
+	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/protocol"
 	"github.com/algorand/go-algorand/rpcs"
 	"github.com/algorand/go-algorand/test/partitiontest"
-	"github.com/stretchr/testify/require"
 )
 
 func makePrivateGenerator(t *testing.T, round uint64, genesis bookkeeping.Genesis) *generator {
@@ -45,7 +47,7 @@ func makePrivateGenerator(t *testing.T, round uint64, genesis bookkeeping.Genesi
 		AssetCreateFraction:          1.0,
 	}
 	cfg.validateWithDefaults(true)
-	publicGenerator, err := MakeGenerator(round, genesis, cfg, true)
+	publicGenerator, err := MakeGenerator(logging.Base(), round, genesis, cfg, true)
 	require.NoError(t, err)
 	return publicGenerator.(*generator)
 }
@@ -355,7 +357,7 @@ func TestAppBoxesOptin(t *testing.T) {
 
 	paySiblingTxn := sgnTxns[1].Txn
 	require.Equal(t, protocol.PaymentTx, paySiblingTxn.Type)
-	
+
 	g.finishRound()
 	// 2nd attempt to optin (with new sender) doesn't get replaced
 	g.startRound()
@@ -723,21 +725,21 @@ func TestCumulativeEffects(t *testing.T) {
 	partitiontest.PartitionTest(t)
 
 	report := Report{
-		TxTypeID("app_boxes_optin"): 	{GenerationCount: uint64(42)},
-		TxTypeID("app_boxes_create"): 	{GenerationCount: uint64(1337)},
-		TxTypeID("pay_pay"):         	{GenerationCount: uint64(999)},
-		TxTypeID("asset_optin_total"): 	{GenerationCount: uint64(13)},
-		TxTypeID("app_boxes_call"):    	{GenerationCount: uint64(413)},
+		TxTypeID("app_boxes_optin"):   {GenerationCount: uint64(42)},
+		TxTypeID("app_boxes_create"):  {GenerationCount: uint64(1337)},
+		TxTypeID("pay_pay"):           {GenerationCount: uint64(999)},
+		TxTypeID("asset_optin_total"): {GenerationCount: uint64(13)},
+		TxTypeID("app_boxes_call"):    {GenerationCount: uint64(413)},
 	}
 
 	expectedEffectsReport := EffectsReport{
-		"app_boxes_optin": 			uint64(42),
-		"app_boxes_create": 		uint64(1337),
-		"pay_pay":         			uint64(999),
-		"asset_optin_total": 		uint64(13),
-		"app_boxes_call":    		uint64(413),
-		"effect_payment_sibling": 	uint64(42) + uint64(1337),
-		"effect_inner_tx": 			uint64(2 * 42),
+		"app_boxes_optin":        uint64(42),
+		"app_boxes_create":       uint64(1337),
+		"pay_pay":                uint64(999),
+		"asset_optin_total":      uint64(13),
+		"app_boxes_call":         uint64(413),
+		"effect_payment_sibling": uint64(42) + uint64(1337),
+		"effect_inner_tx":        uint64(2 * 42),
 	}
 
 	require.Equal(t, expectedEffectsReport, CumulativeEffects(report))
@@ -772,7 +774,7 @@ func TestCountInners(t *testing.T) {
 					InnerTxns: []transactions.SignedTxnWithAD{
 						{
 							ApplyData: transactions.ApplyData{
-									EvalDelta: transactions.EvalDelta{
+								EvalDelta: transactions.EvalDelta{
 									InnerTxns: []transactions.SignedTxnWithAD{{}, {}},
 								},
 							},
@@ -793,4 +795,3 @@ func TestCountInners(t *testing.T) {
 		})
 	}
 }
-

tools/block-generator/generator/generator_ledger.go

@@ -31,7 +31,6 @@ import (
 	"github.com/algorand/go-algorand/ledger"
 	"github.com/algorand/go-algorand/ledger/eval"
 	"github.com/algorand/go-algorand/ledger/ledgercore"
-	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/rpcs"
 )
 
@@ -40,7 +39,7 @@ import (
 func (g *generator) setBlockHeader(cert *rpcs.EncodedBlockCert) {
 	cert.Block.BlockHeader = bookkeeping.BlockHeader{
 		Round:          basics.Round(g.round),
-		TxnCounter: 	g.txnCounter,
+		TxnCounter:     g.txnCounter,
 		Branch:         bookkeeping.BlockHash{},
 		Seed:           committee.Seed{},
 		TxnCommitments: bookkeeping.TxnCommitments{NativeSha512_256Commitment: crypto.Digest{}},
@@ -63,10 +62,9 @@ func (g *generator) setBlockHeader(cert *rpcs.EncodedBlockCert) {
 	}
 }
 
-
 // ---- ledger simulation and introspection ----
 
-// initializeLedger creates a new ledger 
+// initializeLedger creates a new ledger
 func (g *generator) initializeLedger() {
 	genBal := convertToGenesisBalances(g.balances)
 	// add rewards pool with min balance
@@ -85,7 +83,7 @@ func (g *generator) initializeLedger() {
 	} else {
 		prefix = g.genesisID
 	}
-	l, err := ledger.OpenLedger(logging.Base(), prefix, true, ledgercore.InitState{
+	l, err := ledger.OpenLedger(g.log, prefix, true, ledgercore.InitState{
 		Block:       block,
 		Accounts:    bal.Balances,
 		GenesisHash: g.genesisHash,

tools/block-generator/generator/generator_types.go

@@ -26,6 +26,7 @@ import (
 	"github.com/algorand/go-algorand/data/bookkeeping"
 	txn "github.com/algorand/go-algorand/data/transactions"
 	"github.com/algorand/go-algorand/ledger"
+	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/protocol"
 )
 
@@ -42,6 +43,7 @@ type Generator interface {
 
 type generator struct {
 	verbose bool
+	log     logging.Logger
 
 	config GenerationConfig
 
@@ -52,7 +54,7 @@ type generator struct {
 	numAccounts uint64
 
 	// Block stuff
-	round uint64
+	round         uint64
 	txnCounter    uint64
 	prevBlockHash string
 	timestamp     int64

tools/block-generator/generator/server.go

@@ -24,6 +24,7 @@ import (
 	"time"
 
 	"github.com/algorand/go-algorand/data/bookkeeping"
+	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/tools/block-generator/util"
 )
 
@@ -32,7 +33,7 @@ func MakeServer(configFile string, addr string) (*http.Server, Generator) {
 	noOp := func(next http.Handler) http.Handler {
 		return next
 	}
-	return MakeServerWithMiddleware(0, "", configFile, false, addr, noOp)
+	return MakeServerWithMiddleware(nil, 0, "", configFile, false, addr, noOp)
 }
 
 // BlocksMiddleware is a middleware for the blocks endpoint.
@@ -41,7 +42,7 @@ type BlocksMiddleware func(next http.Handler) http.Handler
 // MakeServerWithMiddleware allows injecting a middleware for the blocks handler.
 // This is needed to simplify tests by stopping block production while validation
 // is done on the data.
-func MakeServerWithMiddleware(dbround uint64, genesisFile string, configFile string, verbose bool, addr string, blocksMiddleware BlocksMiddleware) (*http.Server, Generator) {
+func MakeServerWithMiddleware(log logging.Logger, dbround uint64, genesisFile string, configFile string, verbose bool, addr string, blocksMiddleware BlocksMiddleware) (*http.Server, Generator) {
 	cfg, err := initializeConfigFile(configFile)
 	util.MaybeFail(err, "problem loading config file. Use '--config' or create a config file.")
 	var bkGenesis bookkeeping.Genesis
@@ -50,7 +51,7 @@ func MakeServerWithMiddleware(dbround uint64, genesisFile string, configFile str
 		// TODO: consider using bkGenesis to set cfg.NumGenesisAccounts and cfg.GenesisAccountInitialBalance
 		util.MaybeFail(err, "Failed to parse genesis file '%s'", genesisFile)
 	}
-	gen, err := MakeGenerator(dbround, bkGenesis, cfg, verbose)
+	gen, err := MakeGenerator(log, dbround, bkGenesis, cfg, verbose)
 	util.MaybeFail(err, "Failed to make generator with config file '%s'", configFile)
 
 	mux := http.NewServeMux()

tools/block-generator/runner/run.go

@@ -35,9 +35,11 @@ import (
 	"text/template"
 	"time"
 
+	"github.com/algorand/go-deadlock"
+
+	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/tools/block-generator/generator"
 	"github.com/algorand/go-algorand/tools/block-generator/util"
-	"github.com/algorand/go-deadlock"
 )
 
 //go:embed template/conduit.yml.tmpl
@@ -109,7 +111,9 @@ func Run(args Args) error {
 			}
 			runnerArgs := args
 			runnerArgs.Path = path
-			fmt.Printf("%sRunning test for configuration '%s'\n", pad, path)
+			fmt.Println("----------------------------------------")
+			fmt.Printf("%sRunning test for configuration: %s\n", pad, info.Name())
+			fmt.Println("----------------------------------------")
 			return runnerArgs.run(reportDirectory)
 		})
 		if err != nil {
@@ -123,7 +127,8 @@ func (r *Args) run(reportDirectory string) error {
 	baseName := filepath.Base(r.Path)
 	baseNameNoExt := strings.TrimSuffix(baseName, filepath.Ext(baseName))
 	reportfile := path.Join(reportDirectory, fmt.Sprintf("%s.report", baseNameNoExt))
-	logfile := path.Join(reportDirectory, fmt.Sprintf("%s.conduit-log", baseNameNoExt))
+	conduitlogfile := path.Join(reportDirectory, fmt.Sprintf("%s.conduit-log", baseNameNoExt))
+	ledgerlogfile := path.Join(reportDirectory, fmt.Sprintf("%s.ledger-log", baseNameNoExt))
 	dataDir := path.Join(reportDirectory, fmt.Sprintf("%s_data", baseNameNoExt))
 	// create the data directory.
 	if err := os.Mkdir(dataDir, os.ModeDir|os.ModePerm); err != nil {
@@ -162,10 +167,10 @@ func (r *Args) run(reportDirectory string) error {
 	// Start services
 	algodNet := fmt.Sprintf("localhost:%d", 11112)
 	metricsNet := fmt.Sprintf("localhost:%d", r.MetricsPort)
-	generatorShutdownFunc, _ := startGenerator(r.Path, nextRound, r.GenesisFile, r.RunnerVerbose, algodNet, blockMiddleware)
+	generatorShutdownFunc, _ := startGenerator(ledgerlogfile, r.Path, nextRound, r.GenesisFile, r.RunnerVerbose, algodNet, blockMiddleware)
 	defer func() {
 		// Shutdown generator.
-		fmt.Println("Shutting down generator...")
+		fmt.Printf("%sShutting down generator...\n", pad)
 		if err := generatorShutdownFunc(); err != nil {
 			fmt.Printf("failed to shutdown generator: %s\n", err)
 		}
@@ -184,7 +189,7 @@ func (r *Args) run(reportDirectory string) error {
 	defer f.Close()
 	conduitConfig := config{
 		LogLevel:                 r.ConduitLogLevel,
-		LogFile:                  logfile,
+		LogFile:                  conduitlogfile,
 		MetricsPort:              fmt.Sprintf(":%d", r.MetricsPort),
 		AlgodNet:                 algodNet,
 		PostgresConnectionString: r.PostgresConnectionString,
@@ -449,9 +454,15 @@ func (r *Args) runTest(report *os.File, metricsURL string, generatorURL string)
 }
 
 // startGenerator starts the generator server.
-func startGenerator(configFile string, dbround uint64, genesisFile string, verbose bool, addr string, blockMiddleware func(http.Handler) http.Handler) (func() error, generator.Generator) {
+func startGenerator(ledgerLogFile, configFile string, dbround uint64, genesisFile string, verbose bool, addr string, blockMiddleware func(http.Handler) http.Handler) (func() error, generator.Generator) {
+	f, err := os.OpenFile(ledgerLogFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
+	util.MaybeFail(err, "unable to open ledger log file '%s'", ledgerLogFile)
+	log := logging.NewLogger()
+	log.SetLevel(logging.Warn)
+	log.SetOutput(f)
+
 	// Start generator.
-	server, generator := generator.MakeServerWithMiddleware(dbround, genesisFile, configFile, verbose, addr, blockMiddleware)
+	server, generator := generator.MakeServerWithMiddleware(log, dbround, genesisFile, configFile, verbose, addr, blockMiddleware)
 
 	// Start the server
 	go func() {