search

SwitchEV / iso15118

Implementation of the ISO 15118 Communication Protocol (-2, -20, -8)
Apache License 2.0
147 stars 82 forks source link

EXI parsing error for ScheduleExchangeRes #389

Closed heavyweight87 closed 2 months ago

heavyweight87 commented 3 months ago

Hi,

When sending ScheduleExchangeRes from our charger to the switch EV simulator we get an EXI parsing error: Where validation failed: 807004395d2be6f1439e94881d7eaaf062000340

I cannot seem to figure out why it is not working, as every message before this is fine. This same message also works with other testers

Is there any way to get more information about what decoding error there is? Could it be a bug in the java exi parser?

Thanks

shalinnijel2 commented 3 months ago

Hi @heavyweight87, To help validate this - could you also share the ScheduleExchangeRes message itself?

heavyweight87 commented 3 months ago

Hi,

I dont really have a way to send you the exi message as xml but we are sending the minimum required for dynamic mode. It should be the same as the example from the charin interop guide. So our message should look like this: 

<?xml version="1.0" encoding="UTF-8"?>
<p0:ScheduleExchangeRes xmlns:p0="urn:iso:std:iso:15118:-20:CommonMessages"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
 <p1:Header xmlns:p1="urn:iso:std:iso:15118:-20:CommonTypes">
 <p1:SessionID>3933323835363733</p1:SessionID>
 <p1:TimeStamp>1624366044</p1:TimeStamp>
 </p1:Header>
 <p1:ResponseCode xmlns:p1="urn:iso:std:iso:15118:-
20:CommonTypes">OK</p1:ResponseCode>
 <p0:EVSEProcessing>Finished</p0:EVSEProcessing>
 <p0:Dynamic_SEResControlMode></p0:Dynamic_SEResControlMode>
</p0:ScheduleExchangeRes>
shalinnijel2 commented 3 months ago

I quickly gave it a go with both our Rust and Java exi codecs with the stream above and I got this output:

{
    "ScheduleExchangeRes":
    {
        "Dynamic_SEResControlMode":
        {},
        "EVSEProcessing": "Finished",
        "Header":
        {
            "SessionID": "72BA57CDE2873D29",
            "TimeStamp": 1710926721
        },
        "ResponseCode": "OK"
    }
}

The message is valid. Hmm...could you share the ev simulator logs?

heavyweight87 commented 3 months ago

Hi,

I tried wit hthe same sessionID / timestampas you used and got the same results. The log:

INFO    2024-03-21 07:55:08,078 - iso15118.shared.comm_session (432): Sent supportedAppProtocolReq
INFO    2024-03-21 07:55:08,084 - iso15118.shared.comm_session (236): supportedAppProtocolRes received
INFO    2024-03-21 07:55:08,084 - iso15118.evcc.states.sap_states (155): Chosen protocol: ISO_15118_20_DC
INFO    2024-03-21 07:55:08,117 - iso15118.shared.comm_session (432): Sent SessionSetupReq
INFO    2024-03-21 07:55:08,118 - iso15118.shared.states (139): Entered state SessionSetup
INFO    2024-03-21 07:55:08,153 - iso15118.shared.comm_session (236): SessionSetupRes received
INFO    2024-03-21 07:55:08,183 - iso15118.shared.comm_session (432): Sent AuthorizationSetupReq
INFO    2024-03-21 07:55:08,185 - iso15118.shared.states (139): Entered state AuthorizationSetup
INFO    2024-03-21 07:55:08,225 - iso15118.shared.comm_session (236): AuthorizationSetupRes received
INFO    2024-03-21 07:55:08,258 - iso15118.shared.comm_session (432): Sent AuthorizationReq
INFO    2024-03-21 07:55:08,259 - iso15118.shared.states (139): Entered state Authorization
INFO    2024-03-21 07:55:08,294 - iso15118.shared.comm_session (236): AuthorizationRes received
INFO    2024-03-21 07:55:08,329 - iso15118.shared.comm_session (432): Sent ServiceDiscoveryReq
INFO    2024-03-21 07:55:08,330 - iso15118.shared.states (139): Entered state ServiceDiscovery
INFO    2024-03-21 07:55:08,370 - iso15118.shared.comm_session (236): ServiceDiscoveryRes received
INFO    2024-03-21 07:55:08,400 - iso15118.shared.comm_session (432): Sent ServiceDetailReq
INFO    2024-03-21 07:55:08,400 - iso15118.shared.states (139): Entered state ServiceDetail
INFO    2024-03-21 07:55:08,438 - iso15118.shared.comm_session (236): ServiceDetailRes received
INFO    2024-03-21 07:55:08,476 - iso15118.shared.comm_session (432): Sent ServiceDetailReq
INFO    2024-03-21 07:55:08,477 - iso15118.shared.states (139): Entered state ServiceDetail
INFO    2024-03-21 07:55:08,523 - iso15118.shared.comm_session (236): ServiceDetailRes received
INFO    2024-03-21 07:55:08,523 - iso15118.evcc.states.iso15118_20_states (661): Selected Control Mode: 1
INFO    2024-03-21 07:55:08,555 - iso15118.shared.comm_session (432): Sent ServiceSelectionReq
INFO    2024-03-21 07:55:08,555 - iso15118.shared.states (139): Entered state ServiceSelection
INFO    2024-03-21 07:55:08,587 - iso15118.shared.comm_session (236): ServiceSelectionRes received
INFO    2024-03-21 07:55:08,609 - iso15118.shared.comm_session (432): Sent DC_ChargeParameterDiscoveryReq
INFO    2024-03-21 07:55:08,609 - iso15118.shared.states (139): Entered state DCChargeParameterDiscovery
INFO    2024-03-21 07:55:08,634 - iso15118.shared.comm_session (236): DC_ChargeParameterDiscoveryRes received
INFO    2024-03-21 07:55:08,667 - iso15118.shared.comm_session (432): Sent ScheduleExchangeReq
INFO    2024-03-21 07:55:08,668 - iso15118.shared.states (139): Entered state ScheduleExchange
ERROR    2024-03-21 07:55:08,701 - iso15118.shared.comm_session (213): EXI message (ns=urn:iso:std:iso:15118:-20:CommonMessages) where validation failed: 807004149ec3f166abdd39081d7eaaf062000340
INFO    2024-03-21 07:55:08,701 - iso15118.shared.comm_session (398): The data link will terminate in 2 seconds and the TCP connection will close in 5 seconds. 
INFO    2024-03-21 07:55:08,701 - iso15118.shared.comm_session (402): Reason: V2GMessageValidationError occurred while processing message  in state ScheduleExchange : . 
INFO    2024-03-21 07:55:10,704 - iso15118.shared.comm_session (411): terminated the data link
INFO    2024-03-21 07:55:13,709 - iso15118.shared.comm_session (418): TCP connection closed to peer with address ('fe80::42:acff:fe11:2', 50660, 0, 6)
ERROR    2024-03-21 07:55:13,712 - iso15118.evcc.comm_session_handler (563): EVCC tried to initiate a V2GCommunicationSession, but maximum number of SDP retry cycles (1) is now reached. Shutting down high-level communication. Unplug and plug in the cable again if you want to start anew.
shalinnijel2 commented 3 months ago

From the log above, I don't think that it is an EXI error. Would have seen a EXIDecodingError if that was the case. Instead, the failure happened during pydantic validation of the decoded message. Could you rerun the session with debug log level enabled - that might give more clues? I guess you already know but sharing just in case - the setting in the .env file should be set to LOG_LEVEL=DEBUG

heavyweight87 commented 3 months ago

You are correct! Its a phydantic validation issue.

By the way - it actually explains the reason for the validation error in the exception error message. The problem is its lost on the way. If you look at stop_reason in comm_session.py (line 532) it does this:

stop_reason = (
                    f"{exc.__class__.__name__} occurred while processing message "
                    f"{message_name} in state {str(self.current_state)} : {exc}. "
                    f"{additional_info}"
                )

For some reason {exc} doesnt work and the exception reason is lost.

Thats why my original log message was unclear: Reason: V2GMessageValidationError occurred while processing message in state ScheduleExchange : .

Maybe its better to do {exc.reason}

Anyway...

The reason for the error:

Validation error: 1 validation error for ScheduleExchangeRes
Dynamic_SEResControlMode -> __root__
  Exactly one field must be set but 0 are set instead. 
Set fields: []
Field options: ['price_level_schedule', 'PriceLevelSchedule', 'absolute_price_schedule', 'AbsolutePriceSchedule'] (type=value_error). 

Decoded dict: {'ScheduleExchangeRes': {'Header': {'SessionID': '293D87E2CD57BA72', 'TimeStamp': 1710926721}, 'ResponseCode': 'OK', 'EVSEProcessing': 'Finished', 'Dynamic_SEResControlMode': {}}}

All these fields are optional from what I can see in the standard

The vaidation function in question

If you want me to open a PR on this to let me know :)

heavyweight87 commented 3 months ago

PR opened #391 Added some other fixes I noticed whilst testing ISO-20