Closed heavyweight87 closed 5 months ago
Hi @heavyweight87, To help validate this - could you also share the ScheduleExchangeRes message itself?
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>
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?
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.
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
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 :)
PR opened #391 Added some other fixes I noticed whilst testing ISO-20
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