fix(gnovm): show "out of gas" errors (#2365)

[grepsuzette]

The following should fix #2365 when adding a package.

Problem

#2365 (and before it, #1205) described a way where adding packages with insufficient gas very often lead to hard to read errors such as:

Data: internal error
Msg traces:
    0 /me/gno/tm2/pkg/crypto/keys/client/maketx.go:213 - deliver transaction failed: log:recovered: strings/strings.gno:11: {WritePerByte}

Diagnostic

Using the call stack in #2365, the following seems to happen.

While preprocessing some file, a panic with OutOfGasException occurs:

gno/tm2/pkg/store/types/gas.go

Lines 96 to 98 in e7e47d2

	if consumed > g.limit {
	panic(OutOfGasException{descriptor})
	}

Upper level recovers and repanics with error:

gno/gnovm/pkg/gnolang/preprocess.go

Lines 3057 to 3070 in e7e47d2

	func predefineNow(store Store, last BlockNode, d Decl) (Decl, bool) {
	defer func() {
	if r := recover(); r != nil {
	// before re-throwing the error, append location information to message.
	loc := last.GetLocation()
	if nline := d.GetLine(); nline > 0 {
	loc.Line = nline
	}
	if rerr, ok := r.(error); ok {
	// NOTE: gotuna/gorilla expects error exceptions.
	panic(errors.Wrap(rerr, loc.String()))
	} else {
	// NOTE: gotuna/gorilla expects error exceptions.
	panic(fmt.Errorf("%s: %v", loc.String(), r))

Upper level treats it as a banal error (falling in default: rather than OutOfGasException, this snippet is longer, make sure to scroll down):

gno/tm2/pkg/sdk/baseapp.go

Lines 733 to 752 in e7e47d2

	defer func() {
	if r := recover(); r != nil {
	switch ex := r.(type) {
	case store.OutOfGasException:
	log := fmt.Sprintf(
	"out of gas, gasWanted: %d, gasUsed: %d location: %v",
	gasWanted,
	ctx.GasMeter().GasConsumed(),
	ex.Descriptor,
	)
	result.Error = ABCIError(std.ErrOutOfGas(log))
	result.Log = log
	result.GasWanted = gasWanted
	result.GasUsed = ctx.GasMeter().GasConsumed()
	return
	default:
	log := fmt.Sprintf("recovered: %v\nstack:\n%v", r, string(debug.Stack()))
	result.Error = ABCIError(std.ErrInternal(log))
	result.Log = log
	result.GasWanted = gasWanted

Proposed fix

Just add a couple of lines in gno/gnovm/pkg/gnolang/preprocess.go:

func predefineNow(store Store, last BlockNode, d Decl) (Decl, bool) {
	defer func() {
		if r := recover(); r != nil {
			// before re-throwing the error, append location information to message.
			loc := last.GetLocation()
			if nline := d.GetLine(); nline > 0 {
				loc.Line = nline
			}
			if rerr, ok := r.(error); ok {
				// NOTE: gotuna/gorilla expects error exceptions.
				panic(errors.Wrap(rerr, loc.String()))
+			} else if ex, ok := r.(OutOfGasException); ok {
+                panic(ex)
            } else {
				// NOTE: gotuna/gorilla expects error exceptions.
				panic(fmt.Errorf("%s: %v", loc.String(), r))
			}
		}
	}()
	m := make(map[Name]struct{})
	return predefineNow2(store, last, d, m)
}

After recompiling and testing with the modus operandi described in #2365, the error message is now:

Data: out of gas error
Msg Traces:
    0  /me/gno/tm2/pkg/crypto/keys/client/maket
x.go:213 - deliver transaction failed: log:out of gas, gasWanted: 9000000, gasUsed: 9001550 location: WritePerByte

Repeatedly calling with fresh gnodev -minimal each time and adding package now consistently shows this message.

Discussion

There still remains a question about the "NOTE: gotuna/gorilla expects error exceptions".

Think it has to do with gnoweb ability to print failures, e.g. gnoweb uses func makeRequest(log *slog.Logger, cfg *Config, qpath string, data []byte) (res *abci.ResponseQuery, err error).

However BaseApp.runTx will turn the OutOfGasException to a nice ABCIError(std.ErrOutOfGas()).
So, in theory, it should do.

I will do some more test tonight adding many packages from /p/demo.

[codecov]

Codecov Report

Attention: Patch coverage is 0% with 2 lines in your changes missing coverage. Please review.

Project coverage is 54.65%. Comparing base (3901e7e) to head (0b9fccc).
Report is 244 commits behind head on master.

Files with missing lines	Patch %	Lines
gnovm/pkg/gnolang/preprocess.go	0.00%	1 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #2368      +/-   ##
==========================================
- Coverage   54.68%   54.65%   -0.03%     
==========================================
  Files         583      584       +1     
  Lines       78503    78670     +167     
==========================================
+ Hits        42928    42997      +69     
- Misses      32368    32458      +90     
- Partials     3207     3215       +8     

Flag	Coverage Δ
contribs/gnodev	26.00% <ø> (+2.18%)	⬆️
contribs/gnofaucet	14.46% <ø> (-0.86%)	⬇️
contribs/gnokeykc	0.00% <ø> (ø)
contribs/gnomd	0.00% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[ltzmaxwell]

just curious, is it only happening with predefineNow()?

[grepsuzette]

just curious, is it only happening with predefineNow()?

I am not sure, that's why I will try to add many packages.

[grepsuzette]

Tested by manually adding all the packages in /p/demo/, respecting dependencies. I didn't find a problem except the second time calling addpkg with low gas (#2453), hence why "Draft".

But #2453 happens with or without this PR.

[Kouteki]

Fixes #2368

[thehowl]

Can you add a test (I'd say txtar test is better here) which currently leads to an unclear error, but then returns an appropriate message?

Also, I think it's better if, instead of having this at the level of preprocess, we switched the type assertion in keeper.go to use errors.As instead.

tm2/pkg/errors supports the standard Unwrap function, so errors.As should work here.

[grepsuzette]

Can you add a test (I'd say txtar test is better here) which currently leads to an unclear error, but then returns an appropriate message?

Yep, however this issue2365.txtar.txt now seems rather pointless,
as I can not reproduce the issue. Did a git bisect and it doesn't happen since #2504.

[grepsuzette]

Also, I think it's better if, instead of having this at the level of preprocess, we switched the type assertion in keeper.go to use errors.As instead.

tm2/pkg/errors supports the standard Unwrap function, so errors.As should work here.

Took a look, think you mean here, in func (vm *VMKeeper) AddPackage(ctx, msg) error:

gno/gno.land/pkg/sdk/vm/keeper.go

Lines 391 to 460 in fadf622

	if err := gno.TypeCheckMemPackage(memPkg, gnostore); err != nil {
	return ErrTypeCheck(err)
	}
	// Pay deposit from creator.
	pkgAddr := gno.DerivePkgAddr(pkgPath)
	// TODO: ACLs.
	// - if r/system/names does not exists -> skip validation.
	// - loads r/system/names data state.
	if err := vm.checkNamespacePermission(ctx, creator, pkgPath); err != nil {
	return err
	}
	err = vm.bank.SendCoins(ctx, creator, pkgAddr, deposit)
	if err != nil {
	return err
	}
	// Parse and run the files, construct *PV.
	msgCtx := stdlibs.ExecContext{
	ChainID: ctx.ChainID(),
	Height: ctx.BlockHeight(),
	Timestamp: ctx.BlockTime().Unix(),
	Msg: msg,
	OrigCaller: creator.Bech32(),
	OrigSend: deposit,
	OrigSendSpent: new(std.Coins),
	OrigPkgAddr: pkgAddr.Bech32(),
	Banker: NewSDKBanker(vm, ctx),
	EventLogger: ctx.EventLogger(),
	}
	// Parse and run the files, construct *PV.
	m2 := gno.NewMachineWithOptions(
	gno.MachineOptions{
	PkgPath: "",
	Output: os.Stdout, // XXX
	Store: gnostore,
	Alloc: gnostore.GetAllocator(),
	Context: msgCtx,
	MaxCycles: vm.maxCycles,
	GasMeter: ctx.GasMeter(),
	})
	defer m2.Release()
	defer func() {
	if r := recover(); r != nil {
	switch r.(type) {
	case store.OutOfGasException: // panic in consumeGas()
	panic(r)
	default:
	err = errors.Wrap(fmt.Errorf("%v", r), "VM addpkg panic: %v\n%s\n",
	r, m2.String())
	return
	}
	}
	}()
	m2.RunMemPackage(memPkg, true)
	// Log the telemetry
	logTelemetry(
	m2.GasMeter.GasConsumed(),
	m2.Cycles,
	attribute.KeyValue{
	Key: "operation",
	Value: attribute.StringValue("m_addpkg"),
	},
	)
	return nil
	}

Line 391 is where the panic happened (a parent branch that is).
And the recover is defered later, line 436.

I suggest we close this PR, and keep your idea until we get a new reproducible issue. It's going to be tough otherwise to make sure it's correctly implemented.

[thehowl]

Can you add a test (I'd say txtar test is better here) which currently leads to an unclear error, but then returns an appropriate message?

Yep, however this issue2365.txtar.txt now seems rather pointless, as I can not reproduce the issue. Did a git bisect and it doesn't happen since #2504.

Probably related to changing gas values?

Try lowering the -gas-wanted. It should hit the gas limit when we're still in Preprocess. Off the top of my head, we should still be hitting the gas counter while Preprocessing, so this fix should still be valid.

Took a look, think you mean here, in func (vm *VMKeeper) AddPackage(ctx, msg) error:

Okay, I think I understand why it was happening here. With lazy stdlib loading (before #2504), GetPackage could be called by the type checker, invoking a Preprocess. Now it cannot happen anymore, so at least in that case if there is a OutOfGas panic it should just return correctly.

I think more generally we can hit this condition if there is an OutOfGas panic in predefine (and consequently, Preprocess). Both predefine and Preprocess capture and wrap errors. So it's good if we catch any out of gas errors and unwrap them.

So what I'm suggesting is to change all blocks like this one in keeper.go:

		if r := recover(); r != nil {
			switch r.(type) {
			case store.OutOfGasException: // panic in consumeGas()
				panic(r)
			default:
				err = errors.Wrap(fmt.Errorf("%v", r), "VM run main addpkg panic: %v\n%s\n",
					r, m.String())
				return
			}
		}

to use errors.As instead of the type assertion; so it should be able to return a correct error in case of a Preprocess OutOfGas.

[grepsuzette]

Probably related to changing gas values?

Tried a variety of gas values but since #2504 it's only the regular "out of gas error" that is shown.

Okay, I think I understand why it was happening here. With lazy stdlib loading (before #2504), GetPackage could be called by the type checker, invoking a Preprocess. Now it cannot happen anymore, so at least in that case if there is a OutOfGas panic it should just return correctly.

Thanks, good explanation! It explains what I observed: much lower gas consumption (2-3 times less), and no seemingly unrelated panics anymore when running out of gas.

[grepsuzette]

I think more generally we can hit this condition if there is an OutOfGas panic in predefine (and consequently, Preprocess). Both predefine and Preprocess capture and wrap errors. So it's good if we catch any out of gas errors and unwrap them.

Perhaps this is the part which I didn't understand though. OK! Think I know what you mean now.

[thehowl]

Do you think you can find a case where this bug happens?

I expect this to be replicable with low gas values; like between 5k and 500k.

[grepsuzette]

Do you think you can find a case where this bug happens?

I expect this to be replicable with low gas values; like between 5k and 500k.

I already tried with like 20 different low values the other day. Besides, after #2504 it should not happen in this case (addpkg)? We could try to sweep a range incrementally, if it's worth it (i.e. still theoretically possible to reproduce).

[piux2]

I reproduced it and fixed it in a separate PR #2638