ISO handshake failing with where validation failed

[shankari]

After rebuilding with the changes in #102
I consistently get

2025-01-15 04:08:03.099383 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "C774DF7FFF57D4FF"}, "Body": {"ChargeParameterDiscoveryReq": {"RequestedEnergyTransferMode": "AC_single_phase_core", "AC_EVChargeParameter": {"EAmount": {"Value": 60, "Multiplier": 3, "Unit": "Wh"}, "EVMaxVoltage": {"Value": 400, "Multiplier": 0, "Unit": "V"}, "EVMaxCurrent": {"Value": 32000, "Multiplier": -3, "Unit": "A"}, "EVMinCurrent": {"Value": 10, "Multiplier": 0, "Unit": "A"}}}}}}
2025-01-15 04:08:03.683871 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Sent ChargeParameterDiscoveryReq
2025-01-15 04:08:03.684603 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Entered state ChargeParameterDiscovery

2025-01-15 04:08:03.685111 [INFO] iso15118_charge  :: Parameter-phase started

2025-01-15 04:08:03.742526 [INFO] iso15118_charge  :: Selected energy transfer mode: AC_single_phase_core

2025-01-15 04:08:03.744824 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: before adjusting for departure time, max_current 16.000000, nom_voltage 230, pmax 3680, departure_duration 0

2025-01-15 04:08:03.745319 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Requested departure time 0, requested energy 60000.000000
2025-01-15 04:08:03.834923 [INFO] evse_manager_1:  ::                                     CAR ISO V2G ChargeParameterDiscoveryReq
2025-01-15 04:08:03.836360 [INFO] evse_manager_1:  :: EVSE ISO V2G ChargeParameterDiscoveryRes
2025-01-15 04:08:03.920466 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"C774DF7FFF57D4FF"},"Body":{"ChargeParameterDiscoveryRes":{"ResponseCode":"OK","EVSEProcessing":"Finished","SAScheduleList":{"SAScheduleTuple":[{"SAScheduleTupleID":1,"PMaxSchedule":{"PMaxScheduleEntry":[{"RelativeTimeInterval":{"start":0,"duration":86400},"PMax":{"Multiplier":0,"Unit":"W","Value":3680}}]}}]},"AC_EVSEChargeParameter":{"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false},"EVSENominalVoltage":{"Multiplier":0,"Unit":"h","Value":0},"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":160}}}}}}
2025-01-15 04:08:03.922079 [ERRO] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: EXI message (ns=Namespace.ISO_V2_MSG_DEF) where validation failed: 80980231dd37dfffd5f53fd0a000000000002028c140c50e01c0a80000006000001061400200
2025-01-15 04:08:03.922513 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: The data link will SessionStopAction.TERMINATE in 2 seconds and the TCP connection will close in 5 seconds. 
2025-01-15 04:08:03.922600 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Reason: V2GMessageValidationError occurred while processing message  in state ChargeParameterDiscovery : . 
2025-01-15 04:08:05.926645 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: SessionStopAction.TERMINATEd the data link

2025-01-15 04:08:08.937398 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Timeout waiting for next request or peer closed connection

2025-01-15 04:08:08.938369 [INFO] iso15118_charge  :: v2g_handle_connection exited with -1

2025-01-15 04:08:08.938510 [INFO] iso15118_charge  :: Closing TCP connection
2025-01-15 04:08:08.939110 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: TCP connection closed to peer with address ('fe80::42:c0ff:fea8:213', 61341, 0, 130)
2025-01-15 04:08:08.955576 [ERRO] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: 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.

When I was testing with the patches and a compiled container, it worked

2025-01-15 02:03:27.399381 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "740DFD76BF38FBFF"}, "Body": {"ChargeParameterDiscoveryReq": {"RequestedEnergyTransferMode": "AC_single_phase_core", "AC_EVChargeParameter": {"EAmount": {"Value": 60, "Multiplier": 3, "Unit": "Wh"}, "EVMaxVoltage": {"Value": 400, "Multiplier": 0, "Unit": "V"}, "EVMaxCurrent": {"Value": 32000, "Multiplier": -3, "Unit": "A"}, "EVMinCurrent": {"Value": 10, "Multiplier": 0, "Unit": "A"}}}}}}
2025-01-15 02:03:27.940860 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Sent ChargeParameterDiscoveryReq
2025-01-15 02:03:27.941365 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Entered state ChargeParameterDiscovery
2025-01-15 02:03:27.941857 [INFO] iso15118_charge  :: Parameter-phase started
2025-01-15 02:03:27.949127 [INFO] iso15118_charge  :: Selected energy transfer mode: AC_single_phase_core
2025-01-15 02:03:27.952401 [INFO] evse_manager_1:  ::                                     CAR ISO V2G ChargeParameterDiscoveryReq
2025-01-15 02:03:28.045389 [INFO] evse_manager_1:  :: EVSE ISO V2G ChargeParameterDiscoveryRes
2025-01-15 02:03:28.108575 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"740DFD76BF38FBFF"},"Body":{"ChargeParameterDiscoveryRes":{"ResponseCode":"OK","EVSEProcessing":"Finished","SAScheduleList":{"SAScheduleTuple":[{"SAScheduleTupleID":1,"PMaxSchedule":{"PMaxScheduleEntry":[{"RelativeTimeInterval":{"start":0,"duration":86400},"PMax":{"Multiplier":0,"Unit":"W","Value":3680}}]}}]},"AC_EVSEChargeParameter":{"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false},"EVSENominalVoltage":{"Multiplier":-1,"Unit":"V","Value":2300},"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":160}}}}}}
2025-01-15 02:03:28.109684 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: ChargeParameterDiscoveryRes received
SAScheduleTuples are: [SAScheduleTuple(sa_schedule_tuple_id=1, p_max_schedule=PMaxSchedule(schedule_entries=[PMaxScheduleEntry(p_max=PVPMax(value=3680, multiplier=0, unit=<UnitSymbol.WATT: 'W'>), time_interval=RelativeTimeInterval(start=0, duration=86400))]), sales_tariff=None)]
Sim speed is now  1
1736906608.3739874 1736906608.1111593 1
Charging Session Time Elapsed...  0.2629086971282959
In ProcessSchedules
Processing SASchedules! $[]
Processing SASchedules! $0.2629086971282959
Done processing schedules...
About to handle pmax schedule p_max=PVPMax(value=3680, multiplier=0, unit=<UnitSymbol.WATT: 'W'>) time_interval=RelativeTimeInterval(start=0, duration=86400)
pmax=3680
Abt to generate Curve... 0.2629086971282959
Created input array with EAmount=60 and numberSamples=1440
About to generate a new schedule with a EVCC_Profile [ProfileEntryDetails(start=0, max_power=PVPMax(value=3680, multiplier=0, unit=<UnitSymbol.WATT: 'W'>), max_phases_in_use=None), ProfileEntryDetails(start=86400, max_power=PVPMax(value=0, multiplier=0, unit=<UnitSymbol.WATT: 'W'>), max_phases_in_use=None)]
Done
2025-01-15 02:03:31.278681 [INFO] evse_manager_1:  ::                                     CAR IEC Event CarRequestedPower
2025-01-15 02:03:31.282245 [INFO] evse_manager_1:  :: EVSE IEC Charger state: PrepareCharging->Charging
2025-01-15 02:03:31.322821 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Sent PowerDeliveryReq
2025-01-15 02:03:31.323076 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Entered state PowerDelivery

[shankari]

Falling back to AC_three_phase_core didn't work.
Going back to the previously compiled version (0.0.23)

[shankari]

Previously compiled version + 648948c works

[shankari]

Reapplying the single phase changes and they worked too

2025-01-15 05:35:02.113296 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Sent ChargeParameterDiscoveryReq
2025-01-15 05:35:02.113967 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Entered state ChargeParameterDiscovery

2025-01-15 05:35:02.114582 [INFO] iso15118_charge  :: Parameter-phase started

2025-01-15 05:35:02.122503 [INFO] iso15118_charge  :: Selected energy transfer mode: AC_single_phase_core

2025-01-15 05:35:02.123948 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: before adjusting for departure time, max_current 16.000000, nom_voltage 230, pmax 3680, departure_duration 0

2025-01-15 05:35:02.124063 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Requested departure time 0, requested energy 60000.000000
2025-01-15 05:35:02.206284 [INFO] evse_manager_1:  ::                                     CAR ISO V2G ChargeParameterDiscoveryReq
2025-01-15 05:35:02.245714 [INFO] evse_manager_1:  :: EVSE ISO V2G ChargeParameterDiscoveryRes
2025-01-15 05:35:02.251598 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"92C4FD4FDF7F3DBF"},"Body":{"ChargeParameterDiscoveryRes":{"ResponseCode":"OK","EVSEProcessing":"Finished","SAScheduleList":{"SAScheduleTuple":[{"SAScheduleTupleID":1,"PMaxSchedule":{"PMaxScheduleEntry":[{"RelativeTimeInterval":{"start":0,"duration":86400},"PMax":{"Multiplier":0,"Unit":"W","Value":3680}}]}}]},"AC_EVSEChargeParameter":{"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false},"EVSENominalVoltage":{"Multiplier":-1,"Unit":"V","Value":2300},"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":160}}}}}}
2025-01-15 05:35:02.252462 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: ChargeParameterDiscoveryRes received
SAScheduleTuples are: [SAScheduleTuple(sa_schedule_tuple_id=1, p_max_schedule=PMaxSchedule(schedule_entries=[PMaxScheduleEntry(p_max=PVPMax(value=3680, multiplier=0, unit=<UnitSymbol.WATT: 'W'>), time_interval=RelativeTimeInterval(start=0, duration=86400))]), sales_tariff=None)]

The key seems to be that we don't recognize the ChargeParameterDiscoveryRes in the newly built image.
This seems to be a dependency issue, but I am not sure what would change in the dependencies because we have all the dependencies versioned and locked down.

Will try to rebuild, to see if it is a build issue with the new image.
Will fall back to 0.0.23 + manually applied patches instead for tomorrow's demo if that doesn't work.
In that case, we can explore this later, along with improvements to the build pipeline to ensure reproducibility.

[shankari]

Rebuilt with no cache, and can verify that it does not fix the issue.
We still get

2025-01-15 07:28:34.155019 [DEBG] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"16A3F0DFFF6FFE53"},"Body":{"ChargeParameterDiscoveryRes":{"ResponseCode":"OK","EVSEProcessing":"Finished","SAScheduleList":{"SAScheduleTuple":[{"SAScheduleTupleID":1,"PMaxSchedule":{"PMaxScheduleEntry":[{"RelativeTimeInterval":{"start":0,"duration":86400},"PMax":{"Multiplier":0,"Unit":"W","Value":3680}}]}}]},"AC_EVSEChargeParameter":{"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false},"EVSENominalVoltage":{"Multiplier":0,"Unit":"h","Value":0},"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":160}}}}}}
2025-01-15 07:28:34.158473 [ERRO] iso15118_car    pybind11_init_everestpy(pybind11::module_&)::<lambda(const std::string&)> :: EXI message (ns=Namespace.ISO_V2_MSG_DEF) where validation failed: 80980205a8fc37ffdbff94d0a000000000002028c140c50e01c0a80000006000001061400200

Falling back to 0.0.23 + manually applied m3 fix for now. This is almost certainly something stupid, but will investigate tomorrow.