Javascript Processor panic

[ruflin]

• Winlogbeat: 7.3.0

The javascript processors panics with a nil pointer exception. This seems to happen if the data the processor is looking for does not exists or is in the wrong format.

runtime error: invalid memory address or nil pointer dereference [recovered]

        panic: Panic at 0: runtime error: invalid memory address or nil pointer dereference [recovered]

        panic: Panic at 0: runtime error: invalid memory address or nil pointer dereference

[signal 0xc0000005 code=0x0 addr=0x0 pc=0xfe3c8c]

goroutine 615 [running]:

github.com/elastic/beats/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc000a39480)

panic(0x1353e60, 0x11fb1d0)    /usr/local/go/src/runtime/panic.go:522 +0x1c3

github.com/elastic/beats/vendor/github.com/dop251/goja.(*vm).run(0xc00010b040)

github.com/elastic/beats/vendor/github.com/dop251/goja.(*funcObject).Call(0xc00019e180, 0x16e7f20, 0x21a6b00, 0xc0000e9010, 0x1, 0x1, 0x1464c01, 0xc000087200)

github.com/elastic/beats/vendor/github.com/dop251/goja.AssertFunction.func1.2()

github.com/elastic/beats/vendor/github.com/dop251/goja.(*vm).try(0xc00010b040, 0xc000a393f8, 0x0)

github.com/elastic/beats/vendor/github.com/dop251/goja.AssertFunction.func1(0x16e7f20, 0x21a6b00, 0xc0000e9010, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)

github.com/elastic/beats/libbeat/processors/script/javascript.(*session).runProcessFunc(0xc000199090, 0xc0009ad340, 0x0, 0x0, 0x0)

github.com/elastic/beats/libbeat/processors/script/javascript.(*jsProcessor).Run(0xc0001e8fc0, 0xc0009ad340, 0x14e9e46, 0xc0007057d0, 0x0)

github.com/elastic/beats/libbeat/publisher/processing.(*group).Run(0xc000233530, 0xc0009ad340, 0xc0009ad340, 0x0, 0x0)

github.com/elastic/beats/libbeat/publisher/processing.(*group).Run(0xc000730030, 0xc0009ad340, 0x18, 0xc000b9e640, 0x8)

github.com/elastic/beats/libbeat/publisher/pipeline.(*client).publish(0xc0005821e0, 0xebf2f44, 0xed50bf3d8, 0x0, 0x0, 0xc000705440, 0x141d260, 0xc0009ad300, 0x0)

github.com/elastic/beats/libbeat/publisher/pipeline.(*client).Publish(0xc0005821e0, 0xebf2f44, 0xed50bf3d8, 0x0, 0x0, 0xc000705440, 0x141d260, 0xc0009ad300, 0x0)

github.com/elastic/beats/winlogbeat/beater.(*eventLogger).run(0xc000568190, 0xc000110120, 0x16beac0, 0xc0001da280, 0xc00042e210, 0xf, 0x7267ade, 0x36fdc240, 0xed502a632, 0x0, ...)

github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).processEventLog(0xc0001e0000, 0xc00042e5f0, 0xc000568190, 0xc00042e210, 0xf, 0x7267ade, 0x36fdc240, 0xed502a632, 0x0, 0xc0001ca2a0, ... )

created by github.com/elastic/beats/winlogbeat/beater.(*Winlogbeat).Run

[ruflin]

@andrewkroh Pinging you on this one as you might know best.

[andrewkroh]

Do you have the configuration that was being used when this occurred? I think this is the first panic I have encountered from the JS VM. I might need to add a recover statement to enrich the panic with some additional context.

[111andre111]

@andrewkroh Forwarded you configuration

[andrewkroh]

I think we may be able to capture some more debug just be enabling these settings in the configuration file (assuming the file logger is being used which is the default).

logging.files.redirect_stderr: true
logging.level: debug
logging.selectors: [stdlog]

I think this might be able to get us the output from this line which is the JS VM call stack.

beats/vendor/github.com/dop251/goja/vm.go

Line 361 in 0693a22

vm.prg.dumpCode(log.Printf)

I'm still going to add a Go recover() statement to the processor to get more debug info about the Beat event being processed.

[andrewkroh]

I opened a PR to add a the panic recovery with enhanced logging: #13746

[m4rcu5]

I think we may be able to capture some more debug just be enabling these settings in the configuration file (assuming the file logger is being used which is the default).

logging.files.redirect_stderr: true
logging.level: debug
logging.selectors: [stdlog]

Hi, I've recorded the crash using the specified log settings and send them to @111andre111 via the support portal.

Hope it helps debug the issue.

[andrewkroh]

When a processor is defined at the global level it gets created once and used with each internal publisher pipeline that is setup (e.g. one for each Winlogbeat event log reader). I thought the processors were instantiated for each pipeline so the script processor wasn't ready to handle this.

I have opened #13857 to address the issue.