search

EVerest / libocpp

C++ implementation of the Open Charge Point Protocol
Apache License 2.0
97 stars 48 forks source link

Offline transaction seems to require LocalPreAuthorize = true #496

Closed lategoodbye closed 1 month ago

lategoodbye commented 8 months ago

OCPP Version

OCPP1.6

Describe the bug

We noticed the following issue with our Tarragon platform and EVerest core 2024.01. In case the charge point is offline , EVerest seems to require config parameter LocalPreAuthorize = true to authorize a RFID token which actually available via LocalAuthList. We tried to start a transaction via dummy token provider 2 times. The first time the charge point don't know that he's offline and the second time is aware of the offline state. In both cases the charging doesn't start.

Expections: From our understanding this option only applies to online authorization case, which should speedup the authorization process with slow network connections.

To Reproduce

Anything else?

fec 2188000.ethernet eth0: Link is Down
br0: port 1(eth0) entered disabled state
br0: topology change detected, propagating
Feb 26 11:56:01 tarragon manager[2886]: 2024-02-26 11:56:01.974965 [INFO] tarragon_bsp:Cb  :: CP state change from A to C, U_CP+: 6092 mV, U_CP-: 46 mV
Feb 26 11:56:02 tarragon manager[2877]: 2024-02-26 11:56:01.999905 [INFO] connector:EvseM  :: Detected simplified mode.
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.001955 [INFO] hmiled:GpioRgbL  :: Got BSP event "C"
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.002309 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:56:02 tarragon manager[2887]: 2024-02-26 11:56:02.628495 [INFO] tarragon_pluglo  :: plug is locked. Feedback voltage: 631 mV
Feb 26 11:56:02 tarragon manager[2888]: 2024-02-26 11:56:02.807770 [INFO] token_provider_  :: Publishing new dummy token: DEADBEEF (RFID)
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.814877 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "SessionStarted"
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.815309 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:56:02 tarragon manager[2882]: 2024-02-26 11:56:02.816088 [INFO] ocpp:OCPP        :: Connector#1: Received SessionStarted
Feb 26 11:56:02 tarragon manager[2882]: 2024-02-26 11:56:02.816607 [INFO] ocpp:OCPP        :: Logging OCPP messages to html file: /incomplete-ocpp.html
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.855996 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AuthRequired"
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.856379 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:56:02 tarragon manager[2886]: 2024-02-26 11:56:02.859903 [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_32 (U_PP: 1003 mV)
Feb 26 11:56:02 tarragon manager[2876]: 2024-02-26 11:56:02.872481 [INFO] auth:Auth        :: Received new token: {
Feb 26 11:56:02 tarragon manager[2876]:     "authorization_type": "RFID",
Feb 26 11:56:02 tarragon manager[2876]:     "id_token": "DEADBEEF"
Feb 26 11:56:02 tarragon manager[2876]: }
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.929496 [INFO] hmiled:GpioRgbL  :: auth::status_message::token lists no connectors, assuming this event is for us
Feb 26 11:56:02 tarragon manager[2881]: 2024-02-26 11:56:02.930059 [INFO] hmiled:GpioRgbL  :: Auth validation status: Processing
Feb 26 11:56:12 tarragon manager[2876]: 2024-02-26 11:56:12.814741 [INFO] auth:Auth        :: Plug In timeout for connector#1
Feb 26 11:56:12 tarragon manager[2881]: 2024-02-26 11:56:12.942173 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PluginTimeout"
Feb 26 11:56:12 tarragon manager[2881]: 2024-02-26 11:56:12.942613 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:56:42 tarragon manager[2882]: 2024-02-26 11:56:42.820886 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message timeout for: StatusNotification (767ba55b-c0ce-40d7-beae-f270010c2f7e)
Feb 26 11:56:42 tarragon manager[2882]: 2024-02-26 11:56:42.821430 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message is not transaction related, dropping it
Feb 26 11:57:22 tarragon manager[2882]: 2024-02-26 11:57:22.829548 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message timeout for: Authorize (0a271923-30af-48a2-9626-089196968a92)
Feb 26 11:57:22 tarragon manager[2882]: 2024-02-26 11:57:22.829983 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message is not transaction related, dropping it
Feb 26 11:57:22 tarragon manager[2876]: 2024-02-26 11:57:22.863415 [INFO] auth:Auth        :: Result for token: DEADBEEF: REJECTED
Feb 26 11:57:22 tarragon manager[2881]: 2024-02-26 11:57:22.892380 [INFO] hmiled:GpioRgbL  :: auth::status_message::token lists no connectors, assuming this event is for us
Feb 26 11:57:22 tarragon manager[2881]: 2024-02-26 11:57:22.892729 [INFO] hmiled:GpioRgbL  :: Auth validation status: Rejected

Feb 26 11:57:42 tarragon manager[2886]: 2024-02-26 11:57:42.993712 [INFO] tarragon_bsp:Cb  :: CP state change from C to A, U_CP+: 11947 mV, U_CP-: 65 mV
Feb 26 11:57:43 tarragon manager[2881]: 2024-02-26 11:57:43.025108 [INFO] hmiled:GpioRgbL  :: Got BSP event "A"
Feb 26 11:57:43 tarragon manager[2881]: 2024-02-26 11:57:43.025499 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:57:43 tarragon manager[2819]: 2024-02-26 11:57:43.035833 [INFO] manager          :: There are no errors of type evse_board_support/DiodeFault and of module tarragon_bsp->evse_board_support, so no errors are cleared
Feb 26 11:57:43 tarragon manager[2886]: 2024-02-26 11:57:43.079012 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 11:57:43 tarragon manager[2887]: 2024-02-26 11:57:43.885767 [INFO] tarragon_pluglo  :: plug is unlocked. Feedback voltage: 3001 mV
Feb 26 11:57:43 tarragon manager[2881]: 2024-02-26 11:57:43.932452 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "StoppingCharging"
Feb 26 11:57:43 tarragon manager[2881]: 2024-02-26 11:57:43.932851 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:57:43 tarragon manager[2886]: 2024-02-26 11:57:43.952833 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.070826 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "SessionFinished"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.071247 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2886]: 2024-02-26 11:57:44.091634 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 11:57:44 tarragon manager[2819]: 2024-02-26 11:57:44.248516 [INFO] manager          :: There are no errors of type evse_manager/MREC4OverCurrentFailure and of module connector->evse, so no errors are cleared
Feb 26 11:57:44 tarragon manager[2877]: 2024-02-26 11:57:44.313975 [INFO] connector:EvseM  :: All errors cleared
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.346184 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PermanentFaultCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.346580 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.368412 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.368805 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2819]: 2024-02-26 11:57:44.389503 [INFO] manager          :: There are no errors of type evse_manager/Internal and of module connector->evse, so no errors are cleared
Feb 26 11:57:44 tarragon manager[2877]: 2024-02-26 11:57:44.453910 [INFO] connector:EvseM  :: All errors cleared
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.481242 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "ErrorCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.481635 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.502286 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.502672 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2819]: 2024-02-26 11:57:44.527283 [INFO] manager          :: There are no errors of type evse_manager/PowermeterTransactionStartFailed and of module connector->evse, so no errors are cleared
Feb 26 11:57:44 tarragon manager[2877]: 2024-02-26 11:57:44.596709 [INFO] connector:EvseM  :: All errors cleared
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.620123 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PermanentFaultCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.620589 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.651261 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 11:57:44 tarragon manager[2881]: 2024-02-26 11:57:44.651660 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:49 tarragon manager[2886]: 2024-02-26 11:57:49.554871 [INFO] tarragon_bsp:Cb  :: CP state change from A to C, U_CP+: 5920 mV, U_CP-: 46 mV
Feb 26 11:57:49 tarragon manager[2881]: 2024-02-26 11:57:49.585503 [INFO] hmiled:GpioRgbL  :: Got BSP event "C"
Feb 26 11:57:49 tarragon manager[2881]: 2024-02-26 11:57:49.586078 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 11:57:49 tarragon manager[2877]: 2024-02-26 11:57:49.587354 [INFO] connector:EvseM  :: Detected simplified mode.
Feb 26 11:57:50 tarragon manager[2887]: 2024-02-26 11:57:50.213312 [INFO] tarragon_pluglo  :: plug is locked. Feedback voltage: 633 mV
Feb 26 11:57:50 tarragon manager[2888]: 2024-02-26 11:57:50.394026 [INFO] token_provider_  :: Publishing new dummy token: DEADBEEF (RFID)
Feb 26 11:57:50 tarragon manager[2882]: 2024-02-26 11:57:50.404236 [INFO] ocpp:OCPP        :: Connector#1: Received SessionStarted
Feb 26 11:57:50 tarragon manager[2882]: 2024-02-26 11:57:50.404766 [INFO] ocpp:OCPP        :: Logging OCPP messages to html file: /incomplete-ocpp.html
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.407923 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "SessionStarted"
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.408281 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.450104 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AuthRequired"
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.450500 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:57:50 tarragon manager[2886]: 2024-02-26 11:57:50.461391 [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_32 (U_PP: 1003 mV)
Feb 26 11:57:50 tarragon manager[2876]: 2024-02-26 11:57:50.466181 [INFO] auth:Auth        :: Received new token: {
Feb 26 11:57:50 tarragon manager[2876]:     "authorization_type": "RFID",
Feb 26 11:57:50 tarragon manager[2876]:     "id_token": "DEADBEEF"
Feb 26 11:57:50 tarragon manager[2876]: }
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.503984 [INFO] hmiled:GpioRgbL  :: auth::status_message::token lists no connectors, assuming this event is for us
Feb 26 11:57:50 tarragon manager[2881]: 2024-02-26 11:57:50.504365 [INFO] hmiled:GpioRgbL  :: Auth validation status: Processing
Feb 26 11:58:00 tarragon manager[2876]: 2024-02-26 11:58:00.402643 [INFO] auth:Auth        :: Plug In timeout for connector#1
Feb 26 11:58:00 tarragon manager[2881]: 2024-02-26 11:58:00.539259 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PluginTimeout"
Feb 26 11:58:00 tarragon manager[2881]: 2024-02-26 11:58:00.539654 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 11:58:02 tarragon manager[2882]: 2024-02-26 11:58:02.841186 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message timeout for: StatusNotification (da00ed19-cc5d-4b1d-b86a-fbddb59707a9)
Feb 26 11:58:02 tarragon manager[2882]: 2024-02-26 11:58:02.841611 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message is not transaction related, dropping it
Feb 26 11:58:42 tarragon manager[2882]: 2024-02-26 11:58:42.845250 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message timeout for: StatusNotification (71380e7a-36fc-4d43-9051-d9b9ce554cef)
Feb 26 11:58:42 tarragon manager[2882]: 2024-02-26 11:58:42.845796 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message is not transaction related, dropping it
Feb 26 11:59:22 tarragon manager[2882]: 2024-02-26 11:59:22.851680 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message timeout for: StatusNotification (8beec10b-a115-4205-be05-b147805a588c)
Feb 26 11:59:22 tarragon manager[2882]: 2024-02-26 11:59:22.852136 [WARN] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Message is not transaction related, dropping it
Pietfried commented 1 month ago

Hi @lategoodbye , I could not reproduce this with the latest version of libocpp. Offline authorization using cache or local auth list works for me also when LocalPreAuthorize is false. EVerest might not have noticed that the charging station is offline in your case, which requires LocalPreAuthorize to be true to use the cache or auth list.