ocpp1.6: error is swallowed and GenericError on timeout returned instead

[andig]

Here's what's happened in https://github.com/evcc-io/evcc/issues/6817:

enqueued CALL [2627073400, GetConfiguration] for TACW****
dispatched request 2627073400 for TACW****
sent JSON message to TACW****: [2,"2627073400","GetConfiguration",{}]
received JSON message from TACW****: [3, "2627073400", {"configurationKey": [{"key": "GetConfigurationMaxKeys", "readonly": true, "value": "20"}, {"key": "HeartbeatInterval", "readonly": false, "value": "60"}, {"key": "MeterValueSampleInterval", "readonly": false, "value": "30"}, {"key": "AuthorizationKey", "readonly": false}, {"key": "LocalAuthorizeOffline", "readonly": false, "value": "true"}, {"key": "LocalPreAuthorize", "readonly": false, "value": "false"}, {"key": "LocalAuthListEnabled", "readonly": false, "value": "true"}, {"key": "LocalAuthListMaxLength", "readonly": true, "value": "16"}, {"key": "SendLocalListMaxLength", "readonly": true, "value": "8"}, {"key": "SupportedFeatureProfiles", "readonly": true, "value": "Core,FirmwareManagement,LocalAuthListManagement,SmartCharging,RemoteTrigger"}, {"key": "ChargeProfileMaxStackLevel", "readonly": true, "value": "3"}, {"key": "ChargingScheduleAllowedChargingRateUnit", "readonly": true, "value": "Current,Power"}, {"key": "ChargingScheduleMaxPeriods", "readonly": true, "value": "25"}, {"key": "MaxChargingProfilesInstalled", "readonly": true, "value": "16"}, {"key": "NumberOfConnectors", "readonly": true, "value": "1"}, {"key": "AllowOfflineTxForUnknownId", "readonly": false, "value": "false"}, {"key": "AuthorizeRemoteTxRequests", "readonly": false, "value": "false"}, {"key": "ConnectionTimeOut", "readonly": false, "value": "120"}, {"key": "WebSocketPingInterval", "readonly": false, "value": "60"}, {"key": "StopTransactionOnInvalidId", "readonly": false, "value": "true"}, {"key": "MaxEnergyOnInvalidId", "readonly": false, "value": "1000"}, {"key": "MeterValuesAlignedData", "readonly": false, "value": "Energy.Active.Import.Register"}, {"key": "MeterValuesAlignedDataMaxLength", "readonly": true, "value": "4"}, {"key": "ClockAlignedDataInterval", "readonly": false, "value": "0"}, {"key": "MeterValuesSampledData", "readonly": false, "value": "Current.Import,Current.Offered,Energy.Active.Import.Register,Power.Active.Import,Voltage"}, {"key": "MeterValuesSampledDataMaxLength", "readonly": true, "value": "22"}, {"key": "ResetRetries", "readonly": false, "value": "0"}, {"key": "TransactionMessageAttempts", "readonly": false, "value": "10"}, {"key": "TransactionMessageRetryInterval", "readonly": false, "value": "10"}]}]
sent CALL ERROR [2627073400] for TACW****
ocpp message (2627073400): PropertyConstraintViolation - Field CallResult.Payload.ConfigurationKey[3].Value must be maximum 500, but was 0 for feature GetConfiguration

If I don't misjudge this the culprit 3 is

{"key": "AuthorizationKey", "readonly": false}

It looks as if the validation rule in https://github.com/lorenzodonini/ocpp-go/blob/fc83394875b1fc6f96fe4ad46e5d6889c3daa0f4/ocpp1.6/core/get_configuration.go#L15 is mis-triggering? The message is bogus if it's checking for maximum- seems this is more a required fields check?

[andig]

Confirmed. I can repro the error by sending the following Configuration to the CS:

func (handler *ChargePointHandler) OnGetConfiguration(request *core.GetConfigurationRequest) (confirmation *core.GetConfigurationConfirmation, err error) {
    return core.NewGetConfigurationConfirmation([]core.ConfigurationKey{
        {Key: "AuthorizationKey"},
    }), nil
}

[andig]

I've also noticed a follow-on error. The PropertyConstraintViolation is returned from CS to CP. It is not returned to the GetConfiguration() call though. Eventually, GetConfiguration will time out with GenericError which seems really unfortunate as it hides the underlying issue if you have not enabled full logging. Shall I open separate issue for this?

[lorenzodonini]

Nice catch, I'm looking into it and will try to tackle both issues directly, no need to open another issue.

[andig]

Great thank you! This was only possible thanks to the new logging capabilities:)

[andig]

Shall I open separate issue for the error return now or do you think current behaviour is by design? It seems to increase timeout until the error actually occurs at least.

[lorenzodonini]

@andig no need, the other issue is WIP. I closed this issue by mistake. I just reopened it.

[andig]

@lorenzodonini any chance to get this fixed? I had a look at the code but don't quite understand how/where the errors are returned or why the actual error gets swallowed. Would be happy to put up a small bounty!

[lorenzodonini]

@andig I have an open branch with a working solution. Need to write some tests then I'll merge the fix.

[lorenzodonini]

@andig I merged a fix. When a response with an invalid payload is returned, the library will now send an error instead to the requesting endpoint. Let me know if you still encounter any issues.

[andig]

When a response with an invalid payload is returned, the library will now send an error instead to the requesting endpoint.

@lorenzodonini does that only cover invalid payloads or any errors returned by the chargepoint? Imho the expected behaviour would be that any request that the remote endpoint returns an error for returns that error to the caller instead of waiting for timeout.

Is that the correct understanding? I'll merge your changes into our dev environment and check for feedback.

[lorenzodonini]

It covers any error encountered while sending a response, in either direction. For network errors, the timeout/disconnect will still be the quickest indicator though.

Feel free to look at the charge_point.go/sendResponse function logic for more info.

[andig]

Think this one has been fixed, much appreciated!