Merge PR #2285: simulation: Write logs on panic

x/mock/simulation/random_simulate_blocks.go

@@ -7,6 +7,7 @@ import (
 	"math/rand"
 	"os"
 	"os/signal"
+	"runtime/debug"
 	"sort"
 	"strings"
 	"syscall"
@@ -26,9 +27,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 +57,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 +82,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))
+		receivedSignal := <-c
+		fmt.Printf("Exiting early due to %s, on block %d, operation %d\n", receivedSignal, header.Height, opCount)
+		simError = fmt.Errorf("Exited due to %s", receivedSignal)
+		stopEarly = true
 	}()
 
 	var pastTimes []time.Time
@@ -95,15 +98,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 +137,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 +160,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())
 			}
 		}
 	}