From 962b04d98522cddfa94de5ba751a7de34973b01c Mon Sep 17 00:00:00 2001 From: Dev Ojha Date: Tue, 11 Sep 2018 02:18:58 -0700 Subject: [PATCH] Merge PR #2285: simulation: Write logs on panic --- PENDING.md | 1 + cmd/gaia/app/sim_test.go | 9 +++- x/mock/simulation/random_simulate_blocks.go | 48 ++++++++++++++------- x/mock/simulation/util.go | 29 +++++++++++-- 4 files changed, 67 insertions(+), 20 deletions(-) diff --git a/PENDING.md b/PENDING.md index 1acffb10a..b82f34f2e 100644 --- a/PENDING.md +++ b/PENDING.md @@ -107,6 +107,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 diff --git a/cmd/gaia/app/sim_test.go b/cmd/gaia/app/sim_test.go index e809495fc..497aa1383 100644 --- a/cmd/gaia/app/sim_test.go +++ b/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 diff --git a/x/mock/simulation/random_simulate_blocks.go b/x/mock/simulation/random_simulate_blocks.go index 08b70d101..e4a263e23 100644 --- a/x/mock/simulation/random_simulate_blocks.go +++ b/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 diff --git a/x/mock/simulation/util.go b/x/mock/simulation/util.go index d4e1ca1a7..a46d6dd54 100644 --- a/x/mock/simulation/util.go +++ b/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()) } } }