simulation: Write logs on panic

PENDING.md

@@ -106,6 +106,7 @@ IMPROVEMENTS
     * [store] \#1952, \#2281 Update IAVL dependency to v0.11.0
     * [simulation] Make timestamps randomized [#2153](https://github.com/cosmos/cosmos-sdk/pull/2153)
     * [simulation] Make logs not just pure strings, speeding it up by a large factor at greater block heights \#2282
+    * [simulation] Logs get written to file if large, and also get printed on panics \#2285
 
 * Tendermint
 

cmd/gaia/app/sim_test.go

@@ -131,7 +131,7 @@ func BenchmarkFullGaiaSimulation(b *testing.B) {
 
 	// Run randomized simulation
 	// TODO parameterize numbers, save for a later PR
-	simulation.SimulateFromSeed(
+	err := simulation.SimulateFromSeed(
 		b, app.BaseApp, appStateFn, seed,
 		testAndRunTxs(app),
 		[]simulation.RandSetup{},
@@ -140,6 +140,10 @@ func BenchmarkFullGaiaSimulation(b *testing.B) {
 		blockSize,
 		commit,
 	)
+	if err != nil {
+		fmt.Println(err)
+		b.Fail()
+	}
 	if commit {
 		fmt.Println("GoLevelDB Stats")
 		fmt.Println(db.Stats()["leveldb.stats"])
@@ -164,7 +168,7 @@ func TestFullGaiaSimulation(t *testing.T) {
 	require.Equal(t, "GaiaApp", app.Name())
 
 	// Run randomized simulation
-	simulation.SimulateFromSeed(
+	err := simulation.SimulateFromSeed(
 		t, app.BaseApp, appStateFn, seed,
 		testAndRunTxs(app),
 		[]simulation.RandSetup{},
@@ -176,6 +180,7 @@ func TestFullGaiaSimulation(t *testing.T) {
 	if commit {
 		fmt.Println("Database Size", db.Stats()["database.size"])
 	}
+	require.Nil(t, err)
 }
 
 // TODO: Make another test for the fuzzer itself, which just has noOp txs

store/transientstore.go

@@ -1,8 +1,8 @@
 package store
 
 import (
-	dbm "github.com/tendermint/tendermint/libs/db"
 	sdk "github.com/cosmos/cosmos-sdk/types"
+	dbm "github.com/tendermint/tendermint/libs/db"
 )
 
 var _ KVStore = (*transientStore)(nil)

x/mock/simulation/random_simulate_blocks.go

@@ -2,11 +2,13 @@ package simulation
 
 import (
 	"encoding/json"
+	"errors"
 	"fmt"
 	"math"
 	"math/rand"
 	"os"
 	"os/signal"
+	"runtime/debug"
 	"sort"
 	"strings"
 	"syscall"
@@ -26,9 +28,9 @@ import (
 func Simulate(
 	t *testing.T, app *baseapp.BaseApp, appStateFn func(r *rand.Rand, keys []crypto.PrivKey, accs []sdk.AccAddress) json.RawMessage, ops []Operation, setups []RandSetup,
 	invariants []Invariant, numBlocks int, blockSize int, commit bool,
-) {
+) error {
 	time := time.Now().UnixNano()
-	SimulateFromSeed(t, app, appStateFn, time, ops, setups, invariants, numBlocks, blockSize, commit)
+	return SimulateFromSeed(t, app, appStateFn, time, ops, setups, invariants, numBlocks, blockSize, commit)
 }
 
 func initChain(r *rand.Rand, keys []crypto.PrivKey, accs []sdk.AccAddress, setups []RandSetup, app *baseapp.BaseApp,
@@ -56,7 +58,9 @@ func randTimestamp(r *rand.Rand) time.Time {
 func SimulateFromSeed(
 	tb testing.TB, app *baseapp.BaseApp, appStateFn func(r *rand.Rand, keys []crypto.PrivKey, accs []sdk.AccAddress) json.RawMessage, seed int64, ops []Operation, setups []RandSetup,
 	invariants []Invariant, numBlocks int, blockSize int, commit bool,
-) {
+) (simError error) {
+	// in case we have to end early, don't os.Exit so that we can run cleanup code.
+	stopEarly := false
 	testingMode, t, b := getTestingMode(tb)
 	fmt.Printf("Starting SimulateFromSeed with randomness created with seed %d\n", int(seed))
 	r := rand.New(rand.NewSource(seed))
@@ -79,12 +83,12 @@ func SimulateFromSeed(
 
 	// Setup code to catch SIGTERM's
 	c := make(chan os.Signal)
-	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
+	signal.Notify(c, os.Interrupt, syscall.SIGTERM, syscall.SIGINT)
 	go func() {
 		<-c
-		fmt.Printf("Exiting early due to SIGTERM, on block %d, operation %d\n", header.Height, opCount)
-		DisplayEvents(events)
-		os.Exit(128 + int(syscall.SIGTERM))
+		fmt.Printf("Exiting early due to SIGTERM/SIGINT, on block %d, operation %d\n", header.Height, opCount)
+		simError = errors.New("Exited due to SIGTERM/SIGINT")
+		stopEarly = true
 	}()
 
 	var pastTimes []time.Time
@@ -95,15 +99,27 @@ func SimulateFromSeed(
 	operationQueue := make(map[int][]Operation)
 	var blockLogBuilders []*strings.Builder
 
-	if !testingMode {
-		b.ResetTimer()
-	} else {
+	if testingMode {
 		blockLogBuilders = make([]*strings.Builder, numBlocks)
 	}
 	displayLogs := logPrinter(testingMode, blockLogBuilders)
 	blockSimulator := createBlockSimulator(testingMode, tb, t, event, invariants, ops, operationQueue, numBlocks, displayLogs)
+	if !testingMode {
+		b.ResetTimer()
+	} else {
+		// Recover logs in case of panic
+		defer func() {
+			if r := recover(); r != nil {
+				fmt.Println("Panic with err\n", r)
+				stackTrace := string(debug.Stack())
+				fmt.Println(stackTrace)
+				displayLogs()
+				simError = fmt.Errorf("Simulation halted due to panic on block %d", header.Height)
+			}
+		}()
+	}
 
-	for i := 0; i < numBlocks; i++ {
+	for i := 0; i < numBlocks && !stopEarly; i++ {
 		// Log the header time for future lookup
 		pastTimes = append(pastTimes, header.Time)
 		pastSigningValidators = append(pastSigningValidators, request.LastCommitInfo.Validators)
@@ -122,10 +138,9 @@ func SimulateFromSeed(
 
 		// Run queued operations. Ignores blocksize if blocksize is too small
 		numQueuedOpsRan := runQueuedOperations(operationQueue, int(header.Height), tb, r, app, ctx, keys, logWriter, displayLogs, event)
-		opCount += numQueuedOpsRan
 		thisBlockSize -= numQueuedOpsRan
 		operations := blockSimulator(thisBlockSize, r, app, ctx, keys, header, logWriter)
-		opCount += operations
+		opCount += operations + numQueuedOpsRan
 
 		res := app.EndBlock(abci.RequestEndBlock{})
 		header.Height++
@@ -146,9 +161,13 @@ func SimulateFromSeed(
 		// Update the validator set
 		validators = updateValidators(tb, r, validators, res.ValidatorUpdates, event)
 	}
-
+	if stopEarly {
+		DisplayEvents(events)
+		return
+	}
 	fmt.Printf("\nSimulation complete. Final height (blocks): %d, final time (seconds), : %v, operations ran %d\n", header.Height, header.Time, opCount)
 	DisplayEvents(events)
+	return nil
 }
 
 // Returns a function to simulate blocks. Written like this to avoid constant parameters being passed everytime, to minimize

x/mock/simulation/util.go

@@ -3,9 +3,11 @@ package simulation
 import (
 	"fmt"
 	"math/rand"
+	"os"
 	"sort"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/tendermint/tendermint/crypto"
 
@@ -94,13 +96,34 @@ func assertAllInvariants(t *testing.T, app *baseapp.BaseApp, invariants []Invari
 func logPrinter(testingmode bool, logs []*strings.Builder) func() {
 	if testingmode {
 		return func() {
+			numLoggers := 0
 			for i := 0; i < len(logs); i++ {
 				// We're passed the last created block
 				if logs[i] == nil {
-					return
+					numLoggers = i - 1
+					break
+				}
+			}
+			var f *os.File
+			if numLoggers > 10 {
+				fileName := fmt.Sprintf("simulation_log_%s.txt", time.Now().Format("2006-01-02 15:04:05"))
+				fmt.Printf("Too many logs to display, instead writing to %s\n", fileName)
+				f, _ = os.Create(fileName)
+			}
+			for i := 0; i < numLoggers; i++ {
+				if f != nil {
+					_, err := f.WriteString(fmt.Sprintf("Begin block %d\n", i))
+					if err != nil {
+						panic("Failed to write logs to file")
+					}
+					_, err = f.WriteString((*logs[i]).String())
+					if err != nil {
+						panic("Failed to write logs to file")
+					}
+				} else {
+					fmt.Printf("Begin block %d\n", i)
+					fmt.Println((*logs[i]).String())
 				}
-				fmt.Printf("Begin block %d\n", i)
-				fmt.Println((*logs[i]).String())
 			}
 		}
 	}