EXI parsing error for ScheduleExchangeRes

[heavyweight87]

EXI parsing error for ScheduleExchangeRes

[shalinnijel2]

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

[heavyweight87]

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]

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]

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]

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]

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]

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