Unhandled json errors in GetConfiguration

[andig]

In https://github.com/evcc-io/evcc/issues/10339 we've noticed that GetConfiguration requests to charger timed out:

[ocpp  ] TRACE 2023/09/02 12:49:19 sent JSON message to Wall-E: [2,"4010434209","GetConfiguration",{}]
[ocpp  ] TRACE 2023/09/02 12:49:19 received JSON message from Wall-E: [3,"4010434209",{"configurationKey":[{"key":"AuthorizeRemoteTxRequests","readonly":"true","value":"false"},{"key":"ChargeProfileMaxStackLevel","readonly":"true","value":5},{"key":"ChargingScheduleAllowedChargingRateUnit","readonly":"true","value":"W"},{"key":"ChargingScheduleMaxPeriods","readonly":"true","value":20},{"key":"ClockAlignedDataInterval","readonly":"false","value":900},{"key":"ConnectionTimeOut","readonly":"false","value":300},{"key":"ConnectorPhaseRotation","readonly":"false","value":"unknown"},{"key":"GetConfigurationMaxKeys","readonly":"true","value":10},{"key":"HeartbeatInterval","readonly":"false","value":60},{"key":"LocalAuthListEnabled","readonly":"false","value":"false"},{"key":"LocalAuthListMaxLength","readonly":"true","value":20},{"key":"LocalAuthorizeOffline","readonly":"false","value":"true"},{"key":"LocalPreAuthorize","readonly":"false","value":"true"},{"key":"MaxChargingProfilesInstalled","readonly":"true","value":15},{"key":"MeterValueSampleInterval","readonly":"false","value":300},{"key":"MeterValuesAlignedData","readonly":"false","value":"Energy.Active.Import.Register,Power.Active.Import"},{"key":"MeterValuesSampledData","readonly":"false","value":"Energy.Active.Import.Register,Power.Active.Import"},{"key":"NumberOfConnectors","readonly":"true","value":1},{"key":"NumberOfResetRetries","readonly":"false","value":0},{"key":"SendLocalListMaxLength","readonly":"true","value":20},{"key":"StopTransactionOnEVSideDisconnect","readonly":"false","value":"true"},{"key":"StopTransactionOnInvalidId","readonly":"false","value":"false"},{"key":"StopTxnAlignedData","readonly":"false","value":"Energy.Active.Import.Register,Power.Active.Import"},{"key":"StopTxnSampledData","readonly":"false","value":"Energy.Active.Import.Register,Power.Active.Import"},{"key":"SupportedFeatureProfiles","readonly":"true","value":"Core,LocalAuthListManagement,SmartCharging"},{"key":"TransactionMessageAttempts","readonly":"false","value":3},{"key":"TransactionMessageRetryInterval","readonly":"false","value":180},{"key":"UnlockConnectorOnEVSideDisconnect","readonly":"false","value":"false"},{"key":"ckchargepowermax","readonly":"true","value":11000}]}]
[main  ] FATAL 2023/09/02 12:50:19 cannot create charger 'walle': cannot create charger 'template': cannot create charger 'ocpp': ocpp message (4010434209): GenericError - Request timed out

At the same time, we can see that the answer is actually received. Unfortunately, it turns our that the answer is wrong since readonly is encoded as string:

"readonly":"false"

Although we are listening for the Errors() channel, no error is logged. The issue here is that- apart from vendor ignoring the spec- is that the JSON decode error that must have happened is not returned/raised/logged. Extending the TestGetConfigurationConfirmationValidation confirms that:

func (suite *OcppV16TestSuite) TestGetConfigurationConfirmationValidation() {
    type ConfigurationKeyWrong struct {
        Key      string  `json:"key" validate:"required,max=50"`
        Readonly string  `json:"readonly"`
        Value    *string `json:"value,omitempty" validate:"omitempty,max=500"`
    }
    type GetConfigurationConfirmationWrong struct {
        ConfigurationKey []ConfigurationKeyWrong `json:"configurationKey,omitempty" validate:"omitempty,dive"`
    }

    t := suite.T()
    value1 := "value1"
    confirmationTable := []GenericTestEntry{
        // ...
        {GetConfigurationConfirmationWrong{ConfigurationKey: []ConfigurationKeyWrong{{Key: "key1", Readonly: "true", Value: &value1}}}, false},
    }
    // TODO: additional test cases TBD. See get_configuration.go
    ExecuteGenericTestTable(t, confirmationTable)
}

This should fail but doesn't:

--- FAIL: TestOcpp16Protocol (0.00s)
    --- FAIL: TestOcpp16Protocol/TestGetConfigurationConfirmationValidation (0.00s)
        /Users/andig/htdocs/ocpp-go/ocpp1.6_test/ocpp16_test.go:661: 
                Error Trace:    /Users/andig/htdocs/ocpp-go/ocpp1.6_test/ocpp16_test.go:661
                                            /Users/andig/htdocs/ocpp-go/ocpp1.6_test/get_configuration_test.go:53
                Error:          Not equal: 
                                expected: false
                                actual  : true
                Test:           TestOcpp16Protocol/TestGetConfigurationConfirmationValidation
                Messages:       {[{key1 true 0x140004c2e40}]} is valid
FAIL
exit status 1
FAIL    github.com/lorenzodonini/ocpp-go/ocpp1.6_test   1.228s

[andig]

Looking at the code it seems the message goes through

profile.ParseResponse

which will return the json error. It looks as if the error somehow might get swallowed inside

server.ocppMessageHandler

but I'm not sure how that would happen.

[andig]

Not sure that is what we're seeing, but if cp response contains a valid messages id- what it does- cs tries to respond:

// Send error to other endpoint if a message ID is available
if ocppErr.MessageId != "" {
    err2 := s.SendError(wsChannel.ID(), ocppErr.MessageId, ocppErr.Code, ocppErr.Description, nil)
    if err2 != nil {
        return err2
    }
}
log.Error(err)
return err

If that response fails we will never see the original error (which is unfortunate).

That is not the case here though. Why don't we see the error returned?

[andig]

@lorenzodonini any idea why the error is never returned? Do you have an idea how a test for this behaviour could look like?