Panic inside vm.Run

[Bychin]

Hi!

I have encountered a panic inside vm.Run method - runtime error: index out of range [-1].
The code is running 24/7 and the part with expr is used all the time, but the panic occurs ~once per day.

Stacktrace:

runtime.gopanic
	/usr/local/go/src/runtime/panic.go:884
runtime.goPanicIndex
	/usr/local/go/src/runtime/panic.go:113
github.com/antonmedv/expr/vm.(*VM).Run.func1
	/go/pkg/mod/github.com/antonmedv/expr@v1.12.5/vm/vm.go:61
runtime.gopanic
	/usr/local/go/src/runtime/panic.go:884
runtime.panicmem
	/usr/local/go/src/runtime/panic.go:260
runtime.sigpanic
	/usr/local/go/src/runtime/signal_unix.go:839
github.com/antonmedv/expr/vm.(*VM).Run
	/go/pkg/mod/github.com/antonmedv/expr@v1.12.5/vm/vm.go:90

So from what I can see in the source code in github.com/antonmedv/expr/vm/vm.go the first panic was recovered and the second happened inside the defer:

	defer func() {
		if r := recover(); r != nil {
			f := &file.Error{
				Location: program.Locations[vm.ip-1], // <- HERE
				Message:  fmt.Sprintf("%v", r),
			}

Please feel free to ask for more information if you need.

[antonmedv]

The first panic is on the line:

		op := program.Bytecode[vm.ip]

https://github.com/antonmedv/expr/blob/cb1f3459dd4705b6cbaf43069925d5e2c782fd6b/vm/vm.go#L90C1-L90C32

This means that the instruction pointer points to a wrong address.

But this is strange, as a few lines above we have check:

for vm.ip < len(program.Bytecode) {
		if vm.debug {
			<-vm.step
		}

		op := program.Bytecode[vm.ip]

Very interesting.

Is it possible to add a wrapper with recover and log the executed expression?

[antonmedv]

Also, could you make sure that you don't reuse VM in different threads?

[Bychin]

I added wrapper and caught the panic once again (same stacktrace).
Executed expression:

Data.Code == 'XXX' && Parameters.Date.Unix() < ToUnix('2024-01-01')

So, the environment is something like this:

type env struct {
	Data       *DataStruct
	Parameters *ParametersStruct
}

type DataStruct struct {
	Code string
}

type ParametersStruct struct {
	Date time.Time
}

func (e *env) ToUnix(rawDate string) int64 {
	t, err := time.Parse("2006-01-02", rawDate)
	if err != nil {
		panic("invalid rawDate")
	}

	return t.Unix()
}

And ToUnix function is marked as expr.ConstExpr (also there are expr.Optimize(true) and expr.AsBool() options).

I will keep my eye on it to prove that panics happen only for this expression.

I checked the code and seems highly unlikely that VM is being used in different threads.

[antonmedv]

The code looks ok. Lets true to take a look at what program (already compiled) is executed during panic.

Please, log the program as JSON, and as program.Disassemble().

[Bychin]

Should getting the program as JSON be done as something like this json.Marshal(vm.Program.Source)?

[antonmedv]

The whole program. Or some sort of other dump technics you can find out.

[antonmedv]

@Bychin any news on the problem?

[Bychin]

@antonmedv so I wasn't able to reproduce the problems after a little change.

So previously I was using the VM like this:

type Evaluator struct {
	v *vm.VM
}

func (e *Evaluator) Evaluate() error {
	// reuse the same vm instance for performance gain
	v := e.v
	if v == nil {
		v = &vm.VM{}
	}

	... := v.Run(...)

	return nil
}

// WithReusableVM reuses the same vm instance for performance gain.
// It will make the engine not thread safe.
func (e *Evaluator) WithReusableVM() {
	e.v = &vm.VM{}
}

evaluator := &Evaluator{}
if reuseVM {
	evaluator.WithReusableVM() // <- this thing caused the problem
}
evaluator.Evaluate()

evaluator is used in a single thread, but as soon as I stopped reusing VM the problem was gone. I checked the code of v.Run method and I can see that the inner state of VM is cleared before the actual execution, so I don't know where to investigate next.

[antonmedv]

I will close this issue as it not a problem any more. Feel free to create another issue if someone encounters a panic in vm.