Skip to content

Hybrid Compute log levels #575

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
InoMurko merged 3 commits into from
Feb 15, 2023
Merged

Hybrid Compute log levels #575

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
c928827
Reduce the log level of many Turing messages to TRACE.
mmontour1306 Feb 7, 2023
1d3d3a6
More logfile reduction.
mmontour1306 Feb 8, 2023
73504fc
Lowered some more log levels.
mmontour1306 Feb 9, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions l2geth/core/state/statedb.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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
}
Expand Down
2 changes: 1 addition & 1 deletion l2geth/core/types/transaction_meta.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
73 changes: 41 additions & 32 deletions l2geth/core/vm/evm.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand Down Expand Up @@ -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)
}
}
Expand All @@ -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()
}

Expand All @@ -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
Expand Down Expand Up @@ -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
}
Expand All @@ -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)

Expand All @@ -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
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand All @@ -497,15 +497,15 @@ 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)
log.Info("TURING bobaTuringCall:Client error", "err", err)
retError[35] = 13 // Client Error
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])
Expand All @@ -514,24 +514,26 @@ 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
}
// Reassigned the "retError 18: Response too big" check which used to be here

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)
log.Info("TURING bobaTuringCall:Failed to create client for off-chain request", "err", err)
retError[35] = 15 // Could not create client
return retError, 15
}

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))

Expand All @@ -554,12 +556,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)
Expand Down Expand Up @@ -652,15 +654,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
Expand All @@ -669,7 +671,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 {
Expand All @@ -681,7 +683,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
Expand All @@ -691,7 +693,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)
Expand All @@ -701,7 +703,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++
Expand All @@ -710,18 +712,25 @@ 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")
log.Info("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)
}

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),
Expand Down
2 changes: 1 addition & 1 deletion l2geth/rollup/client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down