Running CP against CS crashes CS

[andig]

I'm running the CP against the CS from this repo and CS crashes after a couple of seconds:

CS:

    ❯ gor github.com/lorenzodonini/ocpp-go/example/1.6/cs
    INFO[2020-10-30T14:06:32+01:00] no valid SERVER_LISTEN_PORT environment variable found, using default port 
    INFO[2020-10-30T14:06:32+01:00] starting central system on port 8887         
    INFO[2020-10-30T14:06:44+01:00] new client on URL /evcc                      
    INFO[2020-10-30T14:06:44+01:00] new charge point connected                    client=/evcc
    INFO[2020-10-30T14:06:44+01:00] boot confirmed                                client=/evcc message=BootNotification
    INFO[2020-10-30T14:06:44+01:00] all connectors updated status to Available    client=/evcc message=StatusNotification
    INFO[2020-10-30T14:06:46+01:00] connector 1 reserved for client l33t until 2020-10-30T14:06:46Z (reservation ID 42)  client=/evcc message=ReserveNow
    INFO[2020-10-30T14:06:46+01:00] connector 1 updated status to Reserved        client=/evcc message=StatusNotification
    INFO[2020-10-30T14:06:47+01:00] reservation 42 canceled successfully          client=/evcc message=CancelReservation
    INFO[2020-10-30T14:06:47+01:00] connector 1 updated status to Available       client=/evcc message=StatusNotification
    INFO[2020-10-30T14:06:49+01:00] client authorized                             client=/evcc message=Authorize
    INFO[2020-10-30T14:06:49+01:00] connector 1 updated status to Preparing       client=/evcc message=StatusNotification
    INFO[2020-10-30T14:06:49+01:00] started transaction 0 for connector 1         client=/evcc message=StartTransaction
    INFO[2020-10-30T14:06:49+01:00] connector 1 updated status to Charging        client=/evcc message=StatusNotification
    INFO[2020-10-30T14:06:52+01:00] current local list version: 0                 client=/evcc message=GetLocalListVersion
    panic: runtime error: invalid memory address or nil pointer dereference
    [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x12f786e]

    goroutine 23 [running]:
    main.(*CentralSystemHandler).OnMeterValues(0xc000010190, 0xc00025cfc4, 0x5, 0xc000235b00, 0x0, 0x0, 0x0)
            /Users/andig/htdocs/ocpp-go/example/1.6/cs/handler.go:89 +0x1ee
    github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).handleIncomingRequest.func1(0xc00023ee10, 0xb, 0xc000262850, 0xc00025cfc4, 0x5, 0x1408de0, 0xc000235b00, 0xc000233de0, 0xc000233df0, 0xc00023ee00, ...)
            /Users/andig/htdocs/ocpp-go/ocpp1.6/central_system.go:467 +0x342
    created by github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).handleIncomingRequest
            /Users/andig/htdocs/ocpp-go/ocpp1.6/central_system.go:456 +0x192
    exit status 2

CP:

    ❯ CENTRAL_SYSTEM_URL=ws://localhost:8887 CLIENT_ID=evcc gor github.com/lorenzodonini/ocpp-go/example/1.6/cp
    INFO[2020-10-30T14:06:44+01:00] connected to central system at ws://localhost:8887 
    INFO[2020-10-30T14:06:44+01:00] status: Accepted, interval: 600, current time: 2020-10-30 14:06:44 +0100 CET  message=BootNotification
    INFO[2020-10-30T14:06:44+01:00] status for all connectors updated to Available  message=StatusNotification
    INFO[2020-10-30T14:06:46+01:00] reservation 42 for connector 1 accepted       message=ReserveNow
    INFO[2020-10-30T14:06:46+01:00] status for connector 1 updated to Reserved    message=StatusNotification
    INFO[2020-10-30T14:06:47+01:00] reservation 42 for connector 1 canceled       message=CancelReservation
    INFO[2020-10-30T14:06:47+01:00] status for connector 1 updated to Available   message=StatusNotification
    INFO[2020-10-30T14:06:49+01:00] status: Accepted                              message=Authorize
    INFO[2020-10-30T14:06:49+01:00] status for connector 1 updated to Preparing   message=StatusNotification
    INFO[2020-10-30T14:06:49+01:00] status: Accepted, transaction 0               message=StartTransaction
    INFO[2020-10-30T14:06:49+01:00] status for connector 1 updated to Charging    message=StatusNotification
    INFO[2020-10-30T14:06:52+01:00] returning current local list version: 0       message=GetLocalListVersion
    ^Csignal: interrupt

[andig]

UPDATE: Reason is nil TransactionId being dereferenced in https://github.com/lorenzodonini/ocpp-go/blob/master/example/1.6/cs/handler.go#L89

[lorenzodonini]

You have a very good point there.

I pushed a hotfix and removed the optional TransactionID from the log statement in the Central System handler, which was causing the crash.

[lorenzodonini]

I merged the bugfix to master. If you pull the latest docker images, you will see the correct behavior.

[andig]

Confirmed fixed, but there are a couple of follow-on errors in exampleRoutine. Whenever the client returns

cannot handle call from central system. Sending CallError instead

the CS will crash inside the callback handlers as confirmation will be nil. Could be solved by wrapping each callback handler inside a nil handler.

[lorenzodonini]

Can you send me an example, where this crashes? I thought I was checking for errors for every message sent by the central system.

[andig]

It's the CP sending that crashes the example CS (actually that's another issue than the first one that you've fixed already).

All these callbacks here https://github.com/lorenzodonini/ocpp-go/blob/master/example/1.6/cs/central_system_sim.go#L83 will crash when the confirmation is nil due to the CP replying with an error message.

[lorenzodonini]

That is intended. A CS sends messages asynchronously, so the callback contains both the response (in case there was no error) and the error. It's up to the caller to check whether err != nil.

So the CP doesn't actually crash the CS, it's the application that should check for errors (as you can see in the example).

[andig]

The example cs panics. That cannot be intended?!

[lorenzodonini]

Doesn't panic on latest docker images 🤔

[andig]

I don‘t want to sound like a know-better, but you‘ve fixed the transaction id panics, but not the confirmation nil panics afaiks. I‘ll try to repro again to demonstrate.

[andig]

Here's a another one on StatusNotification. This is, again, against head:

❯ gor github.com/lorenzodonini/ocpp-go/example/1.6/cs
INFO[2020-11-10T10:54:33+01:00] no valid SERVER_LISTEN_PORT environment variable found, using default port 
INFO[2020-11-10T10:54:33+01:00] starting central system on port 8887         
INFO[2020-11-10T10:54:55+01:00] new client on URL /evcc                      
INFO[2020-11-10T10:54:55+01:00] new charge point connected                    client=/evcc
INFO[2020-11-10T10:54:55+01:00] connector 1 updated status to Available       client=/evcc message=StatusNotification
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x12fa0b9]

goroutine 23 [running]:
main.exampleRoutine.func1(0x0, 0x1408b20, 0xc0001c5410)
        /Users/andig/htdocs/ocpp-go/example/1.6/cs/central_system_sim.go:85 +0x679
github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).ReserveNow.func1(0x0, 0x0, 0x1408b20, 0xc0001c5410)
        /Users/andig/htdocs/ocpp-go/ocpp1.6/central_system.go:232 +0x88
github.com/lorenzodonini/ocpp-go/ocpp1%2e6.(*centralSystem).handleIncomingError(0xc0001f2850, 0xc0001ead64, 0x5, 0xc0001c5410, 0x0, 0x0)
        /Users/andig/htdocs/ocpp-go/ocpp1.6/central_system.go:501 +0xe6
github.com/lorenzodonini/ocpp-go/ocppj.(*Server).ocppMessageHandler(0xc0001f27e0, 0x1409240, 0xc0001c4ff0, 0xc00023e000, 0x54, 0x600, 0xc0000f2000, 0x13b9878)
        /Users/andig/htdocs/ocpp-go/ocppj/server.go:217 +0x588
github.com/lorenzodonini/ocpp-go/ws.(*Server).readPump(0xc00008ef50, 0xc0001c4ff0)
        /Users/andig/htdocs/ocpp-go/ws/websocket.go:336 +0x378
created by github.com/lorenzodonini/ocpp-go/ws.(*Server).wsHandler
        /Users/andig/htdocs/ocpp-go/ws/websocket.go:300 +0x457
exit status 2

[lorenzodonini]

Ok, now I see what you mean. Thanks for the trace.

I presume you're using a different charge point implementation/version though, because with the latest docker images I do not get any crashes (mainly, because no errors are ever returned by the charge point sample implementation).

As I mentioned before, the confirmation objects are still supposed to be nil by design, whenever there is an error returned.

To fix the panic, I will simply make sure that confirmation.GetFeatureName() is not called (that's what's causing the panic). Fix incoming soon.

[lorenzodonini]

Solved those panics on CS side in #42. Feel free to checkout that branch and give it a try.