From c928827265cdc046100319029157be3c549bec3e Mon Sep 17 00:00:00 2001 From: Michael Montour Date: Mon, 6 Feb 2023 19:39:42 -0800 Subject: [PATCH 1/3] Reduce the log level of many Turing messages to TRACE. Changes to be committed: modified: l2geth/core/state/statedb.go modified: l2geth/core/vm/evm.go modified: l2geth/rollup/client.go --- l2geth/core/state/statedb.go | 6 ++--- l2geth/core/vm/evm.go | 50 ++++++++++++++++++------------------ l2geth/rollup/client.go | 2 +- 3 files changed, 29 insertions(+), 29 deletions(-) diff --git a/l2geth/core/state/statedb.go b/l2geth/core/state/statedb.go index e73e0e6b8a..bed9e6c971 100644 --- a/l2geth/core/state/statedb.go +++ b/l2geth/core/state/statedb.go @@ -436,7 +436,7 @@ func (s *StateDB) TuringCharge(userID common.Address) error { valueOwner := s.GetState(rcfg.OvmTuringCreditAddress, keyOwner) balOwner := valueOwner.Big() - log.Debug("TURING-CREDIT:Before", "balUser", balUser, "price", price) + log.Trace("TURING-CREDIT:Before", "balUser", balUser, "price", price) if balUser.Cmp(price) < 0 { log.Warn("TURING-CREDIT:Insufficient credit", "balUser", balUser, "price", price) @@ -469,11 +469,11 @@ func (s *StateDB) TuringCheck(userID common.Address) error { price := value.Big() if balUser.Cmp(price) < 0 { - log.Warn("TURING-CREDIT-CHECK:User insufficient credit", "balUser", balUser, "price", price) + log.Trace("TURING-CREDIT-CHECK:User insufficient credit", "balUser", balUser, "price", price) return errors.New("Insufficient Turing credit") } - log.Debug("TURING-CREDIT-CHECK:ok", "balUser", balUser, "price", price) + log.Trace("TURING-CREDIT-CHECK:ok", "balUser", balUser, "price", price) return nil } diff --git a/l2geth/core/vm/evm.go b/l2geth/core/vm/evm.go index 2a3b8691e2..d8db204f88 100644 --- a/l2geth/core/vm/evm.go +++ b/l2geth/core/vm/evm.go @@ -313,10 +313,10 @@ func (cache *turingCache) Get(key common.Hash) []byte { } if ent, hit := cache.entries[key]; hit { if time.Now().Before(ent.expires) { - log.Debug("TURING Cache hit", "key", key, "expires", ent.expires) + log.Trace("TURING Cache hit", "key", key, "expires", ent.expires) ret = ent.value } else { - log.Debug("TURING Cache expired", "key", key, "expires", ent.expires) + log.Trace("TURING Cache expired", "key", key, "expires", ent.expires) delete(cache.entries, key) } } @@ -328,7 +328,7 @@ func (cache *turingCache) Put(key common.Hash, value []byte) { cache.lock.Lock() newEnt := &turingCacheEntry{value: value, expires: time.Now().Add(turingCacheExpire)} cache.entries[key] = newEnt - log.Debug("TURING Cache insert", "key", key, "expires", newEnt.expires) + log.Trace("TURING Cache insert", "key", key, "expires", newEnt.expires) cache.lock.Unlock() } @@ -354,7 +354,7 @@ var tCache turingCache // caller is the address of the TuringHelper contract func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock bool) (hexutil.Bytes, int) { - log.Debug("TURING bobaTuringCall:Caller", "caller", caller.String(), "origin", evm.Context.Origin) + log.Trace("TURING bobaTuringCall:Caller", "caller", caller.String(), "origin", evm.Context.Origin) var responseStringEnc string var responseString []byte @@ -389,14 +389,14 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo rVersion := int(rest[28]) // 0 for legacy, 2 for current if rType != 1 { - log.Error("TURING bobaTuringCall:Wrong state (rType != 1)", "rType", rType) + log.Trace("TURING bobaTuringCall:Wrong state (rType != 1)", "rType", rType) retError[35] = 10 // Wrong input state return retError, 10 } rlen := len(rest) if rlen < 7*32 { - log.Error("TURING bobaTuringCall:Calldata too short", "len < 7*32", rlen) + log.Trace("TURING bobaTuringCall:Calldata too short", "len < 7*32", rlen) retError[35] = 11 // Calldata too short return retError, 11 } @@ -411,7 +411,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo hasher.Write(input) key := common.BytesToHash(hasher.Sum(nil)) - log.Debug("TURING Cache key", "key", key, "mayBlock", mayBlock) + log.Trace("TURING Cache key", "key", key, "mayBlock", mayBlock) ret := tCache.Get(key) @@ -420,7 +420,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo } if len(ret) == 0 { - log.Debug("TURING Missing cache entry", "mayBlock", mayBlock) + log.Trace("TURING Missing cache entry", "mayBlock", mayBlock) if mayBlock { // Since no Boba credit is consumed in an estimateGas call, we put a // "failed" entry into the cache here so that a failed offchain call @@ -472,7 +472,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo // We want the body of the payload without the ABI-encoding length prefix if len(payload) < 64 || (len(payload)%32) != 0 { - log.Error("TURING bad request payload", "len", len(payload)) + log.Trace("TURING bad request payload", "len", len(payload)) retError[35] = 11 // Overloading the "calldata too short", could assign a new error return retError, 11 } @@ -482,7 +482,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo payload = payload[32:] if pLen.Cmp(big.NewInt(int64(len(payload)))) != 0 { - log.Error("TURING bad request payload (length mismatch)", "claimed", pLen, "actual", len(payload)) + log.Trace("TURING bad request payload (length mismatch)", "claimed", pLen, "actual", len(payload)) retError[35] = 11 return retError, 11 } @@ -497,7 +497,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo if client != nil { startT := time.Now() - log.Debug("TURING bobaTuringCall:Calling off-chain client at", "url", url) + log.Trace("TURING bobaTuringCall:Calling off-chain client at", "url", url) err := client.CallTimeout(&responseStringEnc, caller.String(), time.Duration(1200)*time.Millisecond, payload) if err != nil { log.Error("TURING bobaTuringCall:Client error", "err", err) @@ -505,7 +505,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo return retError, 13 } if len(responseStringEnc) > turingMaxLenEnc { - log.Error("TURING bobaTuringCall:Raw response too long", + log.Trace("TURING bobaTuringCall:Raw response too long", "limit", turingMaxLenEnc, "length", len(responseStringEnc), "responseStringEnc", responseStringEnc[:turingMaxLenEnc]) @@ -514,7 +514,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo } responseString, err = hexutil.Decode(responseStringEnc) if err != nil { - log.Error("TURING bobaTuringCall:Error decoding responseString", "err", err) + log.Trace("TURING bobaTuringCall:Error decoding responseString", "err", err) retError[35] = 14 // Client Response Decode Error return retError, 14 } @@ -522,7 +522,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo t := time.Now() elapsed := t.Sub(startT) - log.Debug("TURING API response time", "elapsed", elapsed) + log.Trace("TURING API response time", "elapsed", elapsed) } else { log.Error("TURING bobaTuringCall:Failed to create client for off-chain request", "err", err) retError[35] = 15 // Could not create client @@ -554,12 +554,12 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo ret = append(ret, responseString...) // and tack on the payload if len(ret) > lenLimit { - log.Error("TURING bobaTuringCall:Calldata too long", "limit", turingMaxLenCD, "length", len(ret)) + log.Trace("TURING bobaTuringCall:Calldata too long", "limit", turingMaxLenCD, "length", len(ret)) retError[35] = 18 // Calldata too long return retError, 18 } - log.Debug("TURING bobaTuringCall:Modified parameters", + log.Trace("TURING bobaTuringCall:Modified parameters", "newValue", hexutil.Bytes(ret)) tCache.Put(key, ret) @@ -652,15 +652,15 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas prefix_str := "Regular" if isTuring2 || isGetRand2 { prefix_str = "TURING" - log.Debug("TURING REQUEST START", "input", hexutil.Bytes(input), "len(evm.Context.Turing)", len(evm.Context.Turing)) + log.Trace("TURING REQUEST START", "input", hexutil.Bytes(input), "len(evm.Context.Turing)", len(evm.Context.Turing)) // Check 0. the payload must be at least 36 bytes long if len(input) < 36 { - log.Error("TURING ERROR: INPUT TOO SHORT", "input", input) + log.Debug("TURING ERROR: INPUT TOO SHORT", "input", input) return nil, gas, ErrTuringInputTooShort } // Check 1. can only run Turing once anywhere in the call stack if evm.Context.TuringDepth > 1 { - log.Error("TURING ERROR: DEPTH > 1", "evm.Context.TuringDepth", evm.Context.TuringDepth) + log.Trace("TURING ERROR: DEPTH > 1", "evm.Context.TuringDepth", evm.Context.TuringDepth) return nil, gas, ErrTuringDepth } // Check 2. if we are verifier/replica AND (isTuring2 || isGetRand2), then Turing must have run previously @@ -669,7 +669,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas return nil, gas, ErrTuringEmpty } if evm.StateDB.TuringCheck(caller.Address()) != nil { - log.Error("TURING bobaTuringCall:Insufficient credit") + log.Trace("TURING bobaTuringCall:Insufficient credit") return nil, gas, ErrInsufficientBalance } if evm.Context.Sequencer && len(evm.Context.Turing) < 2 { @@ -681,7 +681,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas // If called from the real sequencer thread, Turing must find a cache entry to avoid blocking other users. // As a hack, look for a zero GasPrice to infer that we are in an eth_estimateGas call stack. mayBlock := (evm.Context.GasPrice.Cmp(bigZero) == 0) - log.Debug("TURING preCall", "mayBlock", mayBlock, "gasPrice", evm.Context.GasPrice) + log.Trace("TURING preCall", "mayBlock", mayBlock, "gasPrice", evm.Context.GasPrice) updated_input, _ = evm.bobaTuringCall(input, caller.Address(), mayBlock) // For compatibility, only apply a charge beyond the legacy size limit @@ -691,7 +691,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas } if contract.Gas <= turingGas { - log.Error("TURING ERROR: Insufficient gas for calldata", "have", contract.Gas, "need", turingGas) + log.Debug("TURING ERROR: Insufficient gas for calldata", "have", contract.Gas, "need", turingGas) return nil, 0, ErrTuringTooLong } else { log.Debug("TURING Deducting calldata gas", "had", contract.Gas, "len", len(updated_input), "Mul", evm.Context.TuringGasMul, "deducting", turingGas) @@ -701,7 +701,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas updated_input = evm.bobaTuringRandom(input, caller.Address()) } // there is no other option ret, err = run(evm, contract, updated_input, false) - log.Debug("TURING NEW CALL", "updated_input", updated_input, "ret", hexutil.Bytes(ret), "err", err) + log.Trace("TURING NEW CALL", "updated_input", updated_input, "ret", hexutil.Bytes(ret), "err", err) // and now, provide the updated_input to the context so that the data can be sent to L1 and the CTC evm.Context.Turing = updated_input evm.Context.TuringDepth++ @@ -710,7 +710,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas // Turing for this Transaction has already been run elsewhere - replay using // information from the EVM context ret, err = run(evm, contract, evm.Context.Turing, false) - log.Debug("TURING REPLAY", "evm.Context.Turing", evm.Context.Turing) + log.Trace("TURING REPLAY", "evm.Context.Turing", evm.Context.Turing) } if evm.StateDB.TuringCharge(caller.Address()) != nil { log.Error("TURING bobaTuringCall:Insufficient credit") @@ -721,7 +721,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas ret, err = run(evm, contract, input, false) } - log.Debug(prefix_str+" evm.go run", // Tagged as Regular or TURING + log.Trace(prefix_str+" evm.go run", // Tagged as Regular or TURING "depth", evm.depth, "contract", contract.CodeAddr, "ret", hexutil.Bytes(ret), diff --git a/l2geth/rollup/client.go b/l2geth/rollup/client.go index cfb643d63c..c46044f07f 100644 --- a/l2geth/rollup/client.go +++ b/l2geth/rollup/client.go @@ -246,7 +246,7 @@ func enqueueToTransaction(enqueue *Enqueue) (*types.Transaction, error) { turing := hexutil.Bytes([]byte{0}) if enqueue.Turing == nil { - log.Info("TURING: rollup/client.go Enqueue tx with nil Turing") + log.Trace("TURING: rollup/client.go Enqueue tx with nil Turing") } else { log.Info("TURING: rollup/client.go Enqueue tx with non-nil Turing", "enqueue_turing", enqueue.Turing) turing = *enqueue.Turing From 1d3d3a6f8ae9a8974585dd0142d233f3dff2669f Mon Sep 17 00:00:00 2001 From: Michael Montour Date: Wed, 8 Feb 2023 14:40:17 -0800 Subject: [PATCH 2/3] More logfile reduction. Changes to be committed: modified: core/types/transaction_meta.go modified: core/vm/evm.go --- l2geth/core/types/transaction_meta.go | 2 +- l2geth/core/vm/evm.go | 11 ++++++++++- 2 files changed, 11 insertions(+), 2 deletions(-) diff --git a/l2geth/core/types/transaction_meta.go b/l2geth/core/types/transaction_meta.go index 1011225951..21006a8e0a 100644 --- a/l2geth/core/types/transaction_meta.go +++ b/l2geth/core/types/transaction_meta.go @@ -153,7 +153,7 @@ func TxMetaDecode(input []byte) (*TransactionMeta, error) { turing, err := common.ReadVarBytes(b, 0, 65508, "Turing") // The "Turing" fieldName string is not important and is only used in error messages if err != nil { if errors.Is(err, io.EOF) { - log.Debug("Legacy block decode - no Turing field - setting to nil") + log.Trace("Legacy block decode - no Turing field - setting to nil") meta.L1Turing = nil } else { return nil, err diff --git a/l2geth/core/vm/evm.go b/l2geth/core/vm/evm.go index d8db204f88..53b06f99ff 100644 --- a/l2geth/core/vm/evm.go +++ b/l2geth/core/vm/evm.go @@ -532,6 +532,8 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo log.Debug("TURING bobaTuringCall:Have valid response from offchain API", "Target", url, "Payload", payload, + "responseLen", len(responseString)) + log.Trace("TURING bobaTuringCall:Full offchain response", "ResponseStringEnc", responseStringEnc, "ResponseString", hexutil.Bytes(responseString)) @@ -716,7 +718,14 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas log.Error("TURING bobaTuringCall:Insufficient credit") return nil, gas, ErrInsufficientBalance } - log.Debug("TURING REQUEST END", "updated_input", updated_input) + + // Arbitrary cutoff; balance of logfile readability vs. having enough info to debug issues + if len(updated_input) > 500 { + log.Trace("TURING REQUEST END", "updated_input (full)", updated_input) + log.Debug("TURING REQUEST END", "updated_input (truncated)", updated_input[:500]) + } else { + log.Debug("TURING REQUEST END", "updated_input", updated_input) + } } else { ret, err = run(evm, contract, input, false) } From 73504fc9ef519b3e8b58eb29416c37279fd9b485 Mon Sep 17 00:00:00 2001 From: Michael Montour Date: Thu, 9 Feb 2023 15:55:24 -0800 Subject: [PATCH 3/3] Lowered some more log levels. Changes to be committed: modified: core/vm/evm.go --- l2geth/core/vm/evm.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/l2geth/core/vm/evm.go b/l2geth/core/vm/evm.go index 53b06f99ff..027cb9a99f 100644 --- a/l2geth/core/vm/evm.go +++ b/l2geth/core/vm/evm.go @@ -240,14 +240,14 @@ func (evm *EVM) bobaTuringRandom(input []byte, caller common.Address) hexutil.By // 1 for Request, 2 for Response, integer >= 10 for various failures rType := int(rest[31]) if rType != 1 { - log.Error("TURING bobaTuringRandom:Wrong state (rType != 1)", "rType", rType) + log.Debug("TURING bobaTuringRandom:Wrong state (rType != 1)", "rType", rType) retError[35] = 10 // Wrong input state return retError } rlen := len(rest) if rlen < 2*32 { - log.Error("TURING bobaTuringRandom:Calldata too short", "len < 2*32", rlen) + log.Debug("TURING bobaTuringRandom:Calldata too short", "len < 2*32", rlen) retError[35] = 11 // Calldata too short return retError } @@ -457,7 +457,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo // Check the URL length // Note: we do not handle URLs that are longer than 64 characters if lengthURL > 64 { - log.Error("TURING bobaTuringCall:URL > 64", "urlLength", lengthURL) + log.Debug("TURING bobaTuringCall:URL > 64", "urlLength", lengthURL) retError[35] = 12 // URL string > 64 bytes return retError, 12 } @@ -500,7 +500,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo log.Trace("TURING bobaTuringCall:Calling off-chain client at", "url", url) err := client.CallTimeout(&responseStringEnc, caller.String(), time.Duration(1200)*time.Millisecond, payload) if err != nil { - log.Error("TURING bobaTuringCall:Client error", "err", err) + log.Info("TURING bobaTuringCall:Client error", "err", err) retError[35] = 13 // Client Error return retError, 13 } @@ -524,7 +524,7 @@ func (evm *EVM) bobaTuringCall(input []byte, caller common.Address, mayBlock boo elapsed := t.Sub(startT) log.Trace("TURING API response time", "elapsed", elapsed) } else { - log.Error("TURING bobaTuringCall:Failed to create client for off-chain request", "err", err) + log.Info("TURING bobaTuringCall:Failed to create client for off-chain request", "err", err) retError[35] = 15 // Could not create client return retError, 15 } @@ -715,7 +715,7 @@ func (evm *EVM) Call(caller ContractRef, addr common.Address, input []byte, gas log.Trace("TURING REPLAY", "evm.Context.Turing", evm.Context.Turing) } if evm.StateDB.TuringCharge(caller.Address()) != nil { - log.Error("TURING bobaTuringCall:Insufficient credit") + log.Info("TURING bobaTuringCall:Insufficient credit") return nil, gas, ErrInsufficientBalance }