Simple corredor script results in "runtime error. invalid memory address or nil pointer dereference"

Hello,

I’m trying to test a simple hello-world corredor script and I’m getting an error when launching the script via a workflow button.

The full error is

Could not execute automation: runtime error. invalid memory address or nil pointer dereferenceCould not execute automation: runtime error. invalid memory address or nil pointer dereference

Here is a screenshot depicting the error

Below are my configurations.

The files involved (these are copied over to the corredor server)
image

What admin panel shows when listing corredor scripts ( I don’t know why the client script doesn’t show up).

The workflow definition.

The workflow button definition

I don’t see any offending logs in the corredor server nor in the corteza server. Both logs level are set to most detailed. What are the next steps to debugging this type of issue? Is corteza known to throw nil reference errors often?

Server connected to the Corredor, that is clear (otherwise you would not be able to see the list of scripts there). But still – could you filter out and share corredor-related lines from corteza server log?
Can you share that hello script as well?

@darh

Here are the corteza server logs

corteza_backend_1   | {"level":"info","ts":1663860923.5565093,"logger":"http.rest","msg":"HTTP request POST /corteza/api/automation/workflows/302915990323232772/exec","requestID":"744f55b14071/LWcqCB1NmV-000049","method":"POST","path":"/corteza/api/automation/workflows/302915990323232772/exec","size":25,"remote":"172.26.0.1"}
corteza_backend_1   | {"level":"debug","ts":1663860923.560177,"logger":"workflow.session","msg":"state change handler","sessionID":303050415350480900,"status":"active","workflowID":302915990323232772}
corteza_backend_1   | {"level":"info","ts":1663860923.8108017,"logger":"http.rest","msg":"HTTP response POST /corteza/api/automation/workflows/302915990323232772/exec","requestID":"744f55b14071/LWcqCB1NmV-000049","method":"POST","path":"/corteza/api/automation/workflows/302915990323232772/exec","status":200,"size":105,"duration":0.254254576}

The corredor server itself has no logs from the request, but here are the logs it outputs on setup

~/repos/region-corteza/corteza_corredor_config$  docker logs $(docker container ls --filter=ancestor=corteza_corteza_corredor --quiet)  --follow
{"level":20,"time":1663847112790,"name":"check","apiBaseURL":"http://corteza_backend:8080/system","msg":"configuring cServer system API","v":1}
{"level":20,"time":1663847112791,"name":"check","apiBaseURL":"http://corteza_backend:8080/compose","msg":"configuring cServer compose API","v":1}
{"level":30,"time":1663847112800,"name":"check","msg":"checking API endpoints","v":1}
{"level":20,"time":1663847112800,"name":"check","baseURL":"https://dfda89ec0218","msg":"frontend settings","v":1}
{"level":30,"time":1663847112801,"name":"check","output":"/tmp/corredor/bundler-dist","msg":"making bundler output directory","v":1}
{"level":20,"time":1663847112801,"name":"check","output":"/tmp/corredor/bundler-dist","msg":"bundler enabled","v":1}
{"level":20,"time":1663847112801,"name":"services.client-scripts","msg":"initializing","v":1}
{"level":20,"time":1663847112801,"name":"services.server-scripts","msg":"initializing","v":1}
{"level":20,"time":1663847112802,"name":"services.dependencies","msg":"initializing","v":1}
{"level":30,"time":1663847112802,"name":"services.dependencies","msg":"initializing watcher","v":1}
{"level":30,"time":1663847112811,"name":"services.server-scripts","searchPaths":["/corredor/usr/*","/corredor/usr","/corredor/corre/extensions","/extensions/*"],"msg":"reloading server scripts","v":1}
{"level":30,"time":1663847112815,"name":"services.client-scripts","searchPaths":["/corredor/usr/*","/corredor/usr","/corredor/corre/extensions","/extensions/*"],"msg":"reloading client scripts","v":1}
{"level":30,"time":1663847112825,"name":"services.client-scripts","valid":0,"total":0,"msg":"processed","v":1}
{"level":30,"time":1663847113008,"name":"services.server-scripts","valid":1,"total":1,"msg":"processed","v":1}
{"level":30,"time":1663847113013,"name":"check","buildTime":"2022-09-22T11:45:09Z","version":"2022.9.0-dev.2","msg":"Assuming valid Corteza API at http://corteza_backend:8080/system","v":1}
{"level":20,"time":1663847113036,"name":"gRPC","msg":"starting server","v":1}
{"level":30,"time":1663847113036,"name":"gRPC","msg":"server running at 0.0.0.0:80","v":1}
{"level":20,"time":1663847115132,"name":"gRPC.ServerScripts","name":"grpc.server-scripts","rpc":"List","filter":{},"total":1,"msg":"returning list of server scripts","v":1}
{"level":20,"time":1663847115147,"name":"gRPC.ClientScripts","name":"grpc.client-scripts","rpc":"List","filter":{},"total":0,"msg":"returning list of client scripts","v":1}

This is the hello world script

export default {
    label: "hello-world-server",
    description: "A sample server automation script",

    // Use the ones you need, delete the rest
    triggers ({ before, after, on, at }) {
        return on('manual').for('system');

    },

    // remove async if you aren't doing any async operations
    // use object destructuring for args and ctx
    async exec(args,ctx) {
        console.log("Hello, world!");
        console.log(args);
        console.log(ctx);
        logger.info('success')
    },
}

Here are the logs from the main corteza web server pertaining to corredor before any user request happens. I’m assuming the errors here are happening since I’m using docker compose and the corteza server starts up a short amount of time before the corredor server. Eventually, it connects and manages to list the scripts (altough one is missing)

{"level":"debug","ts":1663866050.2702003,"logger":"corredor.conn","msg":"connecting without TLS certificates (this is OK if you are using private or internal docker network)"}
{"level":"info","ts":1663866050.2702181,"logger":"corredor.conn","msg":"connecting to corredor","addr":"corteza_corredor:80"}
{"level":"debug","ts":1663866050.281537,"logger":"corredor","msg":"watcher initialized"}
{"level":"error","ts":1663866052.2826989,"logger":"corredor","msg":"could not load corredor server scripts","error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp 172.30.0.2:80: connect: connection refused\""}
{"level":"error","ts":1663866052.2827916,"logger":"corredor","msg":"could not load corredor client scripts","error":"rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = \"transport: Error while dialing dial tcp 172.30.0.2:80: connect: connection refused\""}
{"level":"debug","ts":1663866055.2943718,"logger":"corredor","msg":"reloading server scripts"}
{"level":"debug","ts":1663866055.2944167,"logger":"corredor","msg":"script registered","script":"/server-scripts/hello-world.js:default","explicit":1,"triggers":0}

Any update on this?

@darh

Unfortunately not yet. We are in the middle of preparations for the 2022.9 release this week. I’ll try and find someone that can take a look asap.

1 Like

I figured it out, the “args” cannot be null.

This is a bug (or at least it should be verified).

Here’s the stack trace of the function responsible

step 4 crashed: runtime error: invalid memory address or nil pointer dereference,goroutine 1805 [running]:
runtime/debug.Stack()
        /usr/local/go/src/runtime/debug/stack.go:24 +0x65
github.com/cortezaproject/corteza-server/pkg/wfexec.(*Session).exec.func1()
        /corteza/pkg/wfexec/session.go:645 +0x1bc
panic({0x1c80540, 0x34365f0})
        /usr/local/go/src/runtime/panic.go:844 +0x258
github.com/cortezaproject/corteza-server/pkg/expr.(*Vars).Dict(0x0)
        /corteza/pkg/expr/vars.go:174 +0x50
github.com/cortezaproject/corteza-server/automation/automation.makeScriptArgs(0xc0014c5850?)
        /corteza/automation/automation/corredor_handler.go:65 +0x19
github.com/cortezaproject/corteza-server/automation/automation.corredorHandler.exec({{0xc00136ca20?, 0x1b692c0?}, {0xc001899e60?, 0x0?}}, {0x0?, 0x0?}, 0xc00136c950?)
        /corteza/automation/automation/corredor_handler.go:50 +0x1d
github.com/cortezaproject/corteza-server/automation/automation.corredorHandler.Exec.func1({0x261a8b8, 0xc001899d70}, 0x1?)
        /corteza/automation/automation/corredor_handler.gen.go:95 +0xfc
github.com/cortezaproject/corteza-server/automation/types.functionStep.Exec({{0x4}, 0xc000b8a980, {0xc0002982a0, 0x1, 0x4}, {0x36b4c28, 0x0, 0x0}}, {0x261a8b8, 0xc001899d10}, ...)
        /corteza/automation/types/function.go:109 +0x519
github.com/cortezaproject/corteza-server/pkg/wfexec.(*Session).exec(0xc000fa6270, {0x261a8b8?, 0xc000e2ccf0?}, 0xc000f0c720, 0xc00135a1c0)
        /corteza/pkg/wfexec/session.go:676 +0x4f4
github.com/cortezaproject/corteza-server/pkg/wfexec.(*Session).worker.func2()
        /corteza/pkg/wfexec/session.go:514 +0x1a5
created by github.com/cortezaproject/corteza-server/pkg/wfexec.(*Session).worker
        /corteza/pkg/wfexec/session.go:503 +0x43e

After adding the string {} in script args, it started working