📝 ❇️ Test all SIL/HIL Demos

the-bay-kay commented 1 week ago

Goals

In the final stages of prep for CharIN, we want to exhaustively test a variety of Software-In-the-Loop (SIL) and Hardware-In-the-Loop (HIL) demos that we have developed, to ensure that everything is running smoothly prior to the event. These tests will include (but are not limited to):

[x] All existing demo scripts within the repository
- Note The ReadMe needs to be updated, as the SIL script names have changed! Once the scripts are tested, we should update the "one-line" demos to reflect these changes.
[x] The ISO15118 + IEM + OCPP201 SP-1 Renegotiation demo described in #74
[ ] Testing the latest demos on a Yocto build in QEMU, as in #76

@shankari ,@Abby-Wheelis , @catarial : Tagging for visibility!

the-bay-kay commented 1 week ago

Let me try to replicate your issues now.

Testing the charge parameters EA=60, DT = 3600, SimSpeed = 100x , I'm not seeing any errors...

Logs

``` End Of Schedule:: 3416 NewClockValue:: 3460.5514526367188 3416 Passed the end of the schedule! 2024-11-18 16:16:41.286374 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "83B7E93FEAF3D6BC"}, "Body": {"PowerDeliveryReq": {"ChargeProgress": "Renegotiate", "SAScheduleTupleID": 1}}}} 2024-11-18 16:16:41.806467 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Sent PowerDeliveryReq 2024-11-18 16:16:41.806651 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Entered state PowerDelivery 2024-11-18 16:16:41.837500 [INFO] evse_manager_1: :: CAR ISO V2G PowerDeliveryReq 2024-11-18 16:16:41.905879 [INFO] evse_manager_1: :: EVSE ISO V2G PowerDeliveryRes 2024-11-18 16:16:41.919668 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"83B7E93FEAF3D6BC"},"Body":{"PowerDeliveryRes":{"ResponseCode":"OK","AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false}}}}} 2024-11-18 16:16:41.919964 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: PowerDeliveryRes received 2024-11-18 16:16:41.920518 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "83B7E93FEAF3D6BC"}, "Body": {"ChargeParameterDiscoveryReq": {"RequestedEnergyTransferMode": "AC_three_phase_core", "AC_EVChargeParameter": {"DepartureTime": 3600, "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"}}}}}} 2024-11-18 16:16:42.435804 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Sent ChargeParameterDiscoveryReq 2024-11-18 16:16:42.436025 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Entered state ChargeParameterDiscovery 2024-11-18 16:16:42.436753 [INFO] iso15118_charge :: Selected energy transfer mode: AC_three_phase_core 2024-11-18 16:16:42.436872 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: before adjusting for departure time, max_current 32.000000, nom_voltage 230, pmax 22080, departure_duration 3600 2024-11-18 16:16:42.436965 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Requested departure time 3600, requested energy 60000.000000 2024-11-18 16:16:42.437023 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Departure time specified, checking to see if we can lower requirements 2024-11-18 16:16:42.437062 [WARN] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Min hours to charge 2.717391, requested departure time in hours 0.000000, pmax is unchanged 2024-11-18 16:16:42.552451 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"83B7E93FEAF3D6BC"},"Body":{"ChargeParameterDiscoveryRes":{"ResponseCode":"OK","EVSEProcessing":"Finished","SAScheduleList":{"SAScheduleTuple":[{"SAScheduleTupleID":1,"PMaxSchedule":{"PMaxScheduleEntry":[{"RelativeTimeInterval":{"start":0,"duration":3600},"PMax":{"Multiplier":0,"Unit":"W","Value":22080}}]}}]},"AC_EVSEChargeParameter":{"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false},"EVSENominalVoltage":{"Multiplier":-1,"Unit":"V","Value":2300},"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":320}}}}}} 2024-11-18 16:16:42.552928 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: ChargeParameterDiscoveryRes received SAScheduleTuples are: [SAScheduleTuple(sa_schedule_tuple_id=1, p_max_schedule=PMaxSchedule(schedule_entries=[PMaxScheduleEntry(p_max=PVPMax(value=22080, multiplier=0, unit=), time_interval=RelativeTimeInterval(start=0, duration=3600))]), sales_tariff=None)] 2024-11-18 16:16:42.577843 [INFO] evse_manager_1: :: CAR ISO V2G ChargeParameterDiscoveryReq 2024-11-18 16:16:42.578264 [INFO] evse_manager_1: :: EVSE ISO V2G ChargeParameterDiscoveryRes Sim speed is now 100 1731946602.804891 1731946566.680353 100 Charging Session Time Elapsed... 3612.4579429626465 In ProcessSchedules Processing SASchedules! $[] Processing SASchedules! $3612.4579429626465 Done processing schedules... Abt to generate Curve... 3612.4579429626465 End of Profile! Defaulting to EVCC profile enteries 2024-11-18 16:16:43.059174 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "83B7E93FEAF3D6BC"}, "Body": {"PowerDeliveryReq": {"ChargeProgress": "Start", "SAScheduleTupleID": 1, "ChargingProfile": {"ProfileEntry": [{"ChargingProfileEntryStart": 0, "ChargingProfileEntryMaxPower": {"Value": 22080, "Multiplier": 0, "Unit": "W"}}, {"ChargingProfileEntryStart": 3600, "ChargingProfileEntryMaxPower": {"Value": 0, "Multiplier": 0, "Unit": "W"}}]}}}}} 2024-11-18 16:16:43.574402 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Sent PowerDeliveryReq 2024-11-18 16:16:43.574647 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Entered state PowerDelivery 2024-11-18 16:16:43.575605 [INFO] evse_manager_1: :: CAR ISO V2G PowerDeliveryReq 2024-11-18 16:16:43.674082 [INFO] evse_manager_1: :: EVSE ISO V2G PowerDeliveryRes 2024-11-18 16:16:43.733843 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"83B7E93FEAF3D6BC"},"Body":{"PowerDeliveryRes":{"ResponseCode":"OK","AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false}}}}} 2024-11-18 16:16:43.734156 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: PowerDeliveryRes received 2024-11-18 16:16:43.734385 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Message to encode (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message": {"Header": {"SessionID": "83B7E93FEAF3D6BC"}, "Body": {"ChargingStatusReq": {}}}} 2024-11-18 16:16:44.251667 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Sent ChargingStatusReq 2024-11-18 16:16:44.251848 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Entered state ChargingStatus 2024-11-18 16:16:44.277622 [INFO] evse_manager_1: :: CAR ISO V2G ChargingStatusReq 2024-11-18 16:16:44.350017 [INFO] evse_manager_1: :: EVSE ISO V2G ChargingStatusRes 2024-11-18 16:16:44.363358 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: Decoded message (ns=Namespace.ISO_V2_MSG_DEF): {"V2G_Message":{"Header":{"SessionID":"83B7E93FEAF3D6BC"},"Body":{"ChargingStatusRes":{"ResponseCode":"OK","EVSEID":"DE*PNX*00001","SAScheduleTupleID":1,"EVSEMaxCurrent":{"Multiplier":-1,"Unit":"A","Value":320},"MeterInfo":{"MeterID":"YETI_POWERMETER","MeterReading":100},"AC_EVSEStatus":{"NotificationMaxDelay":0,"EVSENotification":"None","RCD":false}}}}} 2024-11-18 16:16:44.363777 [DEBG] iso15118_car pybind11_init_everestpy(pybind11::module_&):: :: ChargingStatusRes received End Of Schedule:: 86400 NewClockValue:: 3768.3791637420654 ```

Let me test a few other input combinations -- It may be that we're incorrectly flagging the end of profile in some scenarios...

[x] {EA: 40, DT: 4000} @ 100x: OK

shankari commented 1 week ago

@the-bay-kay you should be able to use the parameters that I used back in my logs https://github.com/EVerest/everest-demo/issues/84#issuecomment-2480739307

the-bay-kay commented 1 week ago

...you should be able to use the parameters that I used back in my logs...

Ah, yup -- with {EA: 60, DT: 3200} @ 25x, I'm seeing the crash. Let me investigate further...

Abby-Wheelis commented 1 week ago

Took about an hour, but I just got to test - documenting and attaching logs then signing off for the week to put my head down on some code changes for other projects.

1st try - no departure time set, entered charging fine 2nd try - set 4,000 as departure time, entered charging but got an error about max number of SDP retry cycles reached, didn't seem to stop charging (by that I mean the error did not cause charging to stop, I was able to unplug just fine) 3rd try - set 3,000 as departure time, did not enter charging, timed out first and went to "car paused" state

I think it was just 3 tries, my brain is admittedly not keeping up well with me today. @catarial was looking over my shoulder so might be able to account for what happened too.

Logs: Nov18_logs.rtf.zip

catarial commented 1 week ago

I'm getting these errors inconsistently with demo-iso15118-2-ocpp-201 which cause the charger to go from PrepareCharging to CarPaused.

2024-11-18 22:21:42.930580 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: Reading from tcp-socket aborted

2024-11-18 22:21:42.931161 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: connection_read(header) failed: connection terminated

2024-11-18 22:21:42.931414 [ERRO] iso15118_charge void dlog_func(dloglevel_t, const char*, int, const char*, const char*, ...) :: v2g_incoming_v2gtp() (previous message "Payment Service Selection") failed

2024-11-18 22:21:49.972675 [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.
Traceback (most recent call last):
  File "/ext/dist/libexec/everest/modules/PyEvJosev/../../3rd_party/josev/iso15118/evcc/comm_session_handler.py", line 586, in get_from_rcv_queue
    await self.restart_sdp(True)
  File "/ext/dist/libexec/everest/modules/PyEvJosev/../../3rd_party/josev/iso15118/evcc/comm_session_handler.py", line 403, in restart_sdp
    raise SDPFailedError(
iso15118.shared.exceptions.SDPFailedError: 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.

shankari commented 1 week ago

@catarial they may be related to the setting that you commented out "Reading from tcp-socket aborted" That is not necessarily a deal-breaker - it is better to work sometimes than to never work at all. But it would be interesting to see why that line was added by looking at the blame.

I also want to highlight that we could also choose to rebuild multi-platform and see if that works better. I am a bit surprised that this happened in the python code given that python is a scripted language. But it looks like the python networking stack may be a thin layer over the underlying C stack, and this flag may just be different between operating systems. Would be interesting to understand that flag in greater detail, including differences between platforms.

shankari commented 1 week ago

This still has the crashing issue, but that is not a blocker for the testival. Moving it out of the milestone.

EVerest / everest-demo

📝 ❇️ Test all SIL/HIL Demos #84

Goals