EvseManager: PWM switches too fast, timeouts don't take switching into consideration

[barsnick]

Describe the bug

Hi,
I have a situation where the EvseManager feels the need to toggle the PWM, does so too quickly, and also runs into an error which shouldn't occur

EVerest Domain

Charge Control

Affected EVerest Module

EvseManager

To Reproduce

The basic scenario is a bit hypothetical through the use of a manual tester (Metrel) as EV, but runs into real-world problems:

While the EVerest stack launches (or restarts after a power failure), my vehicle is connected in CP State C.

The stack comes up, the BSP reports state C. A new transaction is start. The token (DummyTokenProvider) is verified from its cache. PWM is enabled and the contactors are closed.

In the meantime, OCPP connects to the backend, and synchronizes the system time from the BootNotification. The (major or minor) jump in time causes the power budget to momentarily expire. (BTW, tons of uselessly repeated warnings - I will open a bug or PR for that). Therefore, EvseManager switches PWM to 100 %. (My EV is a manual tester, so it remains in CP State C, but this is not cause of the issue.)

Suddenly (often within about a second), apparently a new power budget is calculated and provided to the EV via PWM, and the PWM goes back to nominal duty cycle. So the EV is probably acting correctly with not yet switching to state B, as it had six seconds to do so, and PWM went back on after just one second.

Yet the timer for the EV to switch to CP State B expires nevertheless, and EvseManager forces PWM off again and opens the contactors.

Two related, but separate things are buggy in our opinion:

1. PWM should not change so quickly. IEC 61851 says 5 seconds. (Refer to IEC 61851-1:2019 "Sequence 6 Current change".) This should probably also apply to toggling of X1/X2.
2. If PWM is provided again before the timeout of the "C->B" requirement (Sequence 10.1 and 10.2), the timer should be erased. We don't see that the EV needs to fulfill C->B if PWM is switched on again within t16-t13.

Anything else?

A log excerpt to show what is happening:

2025-02-27T11:10:21.553423+0100 tarragon manager[30215]: [INFO] auth:Auth        :: Providing authorization to evse#1
2025-02-27T11:10:21.808173+0100 tarragon manager[30111]: [INFO] ocpp:OCPP201     :: OCPP client successfully connected to server with version: ocpp2.0.1
2025-02-27T11:10:21.878550+0100 tarragon manager[30215]: [INFO] auth:Auth        :: Result for token: [redacted] hash: F5EBF4C3: ACCEPTED
2025-02-27T11:10:22.141370+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: handle_pwm_on: Setting new duty cycle of 21.67% (13.0 A)
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]: [INFO] ocpp:OCPP201     :: Received BootNotificationResponse: {
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]:     "currentTime": "2025-02-27T10:10:34.000Z",
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]:     "interval": 60,
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]:     "status": "Accepted"
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]: }
2025-02-27T11:10:22.175812+0100 tarragon manager[30111]: with messageId: a4b8a984-72ad-4c3c-ba97-e6b686360d81
2025-02-27T11:10:22.388964+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: handle_allow_power_on: request to CLOSE the contactor
2025-02-27T11:10:22.388964+0100 tarragon manager[30083]: [WARN] tarragon_bsp:Cb virtual void module::evse_board_support::evse_board_supportImpl::handle_allow_power_on(types::evse_board_support::PowerOnOff&) :: Contactor close throttling in effect: closing will be delayed by 0.7s
2025-02-27T11:10:23.178233+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: Current state: Contactor@R1-S1 (CLOSED, CLOSED)
2025-02-27T11:10:34.065076+0100 tarragon manager[30126]: [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. Last update: 2025-02-27T10:10:30.643Z Now:2025-02-27T10:10:34.061Z
2025-02-27T11:10:34.065076+0100 tarragon manager[30126]: [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. Last update: 2025-02-27T10:10:30.643Z Now:2025-02-27T10:10:34.062Z
2025-02-27T11:10:34.280106+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
2025-02-27T11:10:34.390647+0100 tarragon manager[30126]: [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. Last update: 2025-02-27T10:10:30.643Z Now:2025-02-27T10:10:34.390Z
2025-02-27T11:10:34.491303+0100 tarragon manager[30126]: [WARN] connector_1:Evs bool module::Charger::power_available() :: Power budget expired, falling back to 0. Last update: 2025-02-27T10:10:30.643Z Now:2025-02-27T10:10:34.490Z
2025-02-27T11:10:34.896283+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: handle_pwm_on: Setting new duty cycle of 21.67% (13.0 A)
2025-02-27T11:10:35.054493+0100 tarragon manager[30083]: [WARN] tarragon_bsp:Cb virtual void module::evse_board_support::evse_board_supportImpl::handle_allow_power_on(types::evse_board_support::PowerOnOff&) :: Contactor close throttling in effect: closing will be delayed by 7.4s
2025-02-27T11:10:42.468295+0100 tarragon manager[30126]: [WARN] connector_1:Evs std::queue<module::CPEvent> module::IECStateMachine::state_machine() :: Timeout of 6 seconds reached, EV did not go back to state B after PWM was switch off. Power off under load.
2025-02-27T11:10:42.519917+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: handle_allow_power_on: request to OPEN the contactor
2025-02-27T11:10:42.569200+0100 tarragon manager[30083]: [INFO] tarragon_bsp:Cb  :: Current state: Contactor@R1-S1 (OPEN, OPEN)

(Some OCPP OCSP cache messages and EvseSecurity PnC certificate messages redacted for brevity.)

See how the duty cycle goes from 21 to 100 to 21 %, and the contactor is opened in X2, without switching to X1.

Yes, the power budget expires when the clock jumps forward. This may be okay, as the budget schedules probably need a common (system) clock and not necessarily a "steady_clock".