StopTransaction contains transactionId -1 in OCPP 1.6 start offline case

lategoodbye commented 6 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 we start an offline transaction and stop it online the stopTransaction contains transactionId -1. But the expected behavior would be that EVerest replace the bogus transactionId with the real value from the previous StartTransaction.Conf. Otherwise the transaction will be running endlessly.

OCPP communication with Steve as backend (shouldn't matter)

[INFO ] 2024-02-26 09:14:46,425 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"2e55de9d-3fea-4782-9b57-2bc027976a31","StatusNotification",{"connectorId":1,"errorCode":"NoError","info":"EVConnected","status":"Preparing","timestamp":"2024-02-26T09:12:49.706Z"}]
[INFO ] 2024-02-26 09:14:46,434 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"2e55de9d-3fea-4782-9b57-2bc027976a31",{}]
[INFO ] 2024-02-26 09:14:46,435 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"941dfb0b-b995-45f5-9833-9dfb3f60dcfb","StartTransaction",{"connectorId":1,"idTag":"DEADBEEF","meterStart":971,"timestamp":"2024-02-26T09:12:50.059Z"}]
[INFO ] 2024-02-26 09:14:46,841 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"941dfb0b-b995-45f5-9833-9dfb3f60dcfb",{"transactionId":1458,"idTagInfo":{"status":"Accepted","expiryDate":"2024-02-26T10:14:46.831Z"}}]
[INFO ] 2024-02-26 09:14:46,845 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"cd52d42c-69f7-4f08-b52d-27dd44516a49","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-02-26T09:12:50.265Z"}]
[INFO ] 2024-02-26 09:14:46,850 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"cd52d42c-69f7-4f08-b52d-27dd44516a49",{}]
[INFO ] 2024-02-26 09:14:46,864 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"036b161b-7291-4549-b6ef-5ad88d11b1af","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Finishing","timestamp":"2024-02-26T09:14:44.244Z"}]
[INFO ] 2024-02-26 09:14:46,869 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"036b161b-7291-4549-b6ef-5ad88d11b1af",{}]
[INFO ] 2024-02-26 09:14:46,881 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"5f90e0ca-7ddc-4e66-9cb9-8f9d47b98a3b","StopTransaction",{"meterStop":971,"reason":"EVDisconnected","timestamp":"2024-02-26T09:14:44.157Z","transactionId":-1}]

To Reproduce

configure charge point ( LocalAuthorizeOffline : true, LocalPreAuthorize : true )
let charge point connect to CSMS and let it transfer all OCPP messages
physically disconnect charge point from CSMS (Ethernet)
start charging with dummy token provider and EV simulator ( CP state A -> C )
wait until EVerest noticed offline state
phyiscally reconnect charge point to CSMS (Ethernet)
disconnect EV ( CP state C -> A )

Anything else?

EVerest log:

fec 2188000.ethernet eth0: Link is Down
br0: port 1(eth0) entered disabled state
br0: topology change detected, propagating
Feb 26 10:12:48 tarragon manager[1632]: 2024-02-26 10:12:48.850885 [INFO] tarragon_bsp:Cb  :: CP state change from A to C, U_CP+: 5900 mV, U_CP-: 55 mV
Feb 26 10:12:48 tarragon manager[1627]: 2024-02-26 10:12:48.869296 [INFO] hmiled:GpioRgbL  :: Got BSP event "C"
Feb 26 10:12:48 tarragon manager[1627]: 2024-02-26 10:12:48.869692 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:12:48 tarragon manager[1623]: 2024-02-26 10:12:48.872125 [INFO] connector:EvseM  :: Detected simplified mode.
Feb 26 10:12:49 tarragon manager[1633]: 2024-02-26 10:12:49.496864 [INFO] tarragon_pluglo  :: plug is locked. Feedback voltage: 631 mV
Feb 26 10:12:49 tarragon manager[1628]: 2024-02-26 10:12:49.687736 [INFO] ocpp:OCPP        :: Connector#1: Received SessionStarted
Feb 26 10:12:49 tarragon manager[1628]: 2024-02-26 10:12:49.688356 [INFO] ocpp:OCPP        :: Logging OCPP messages to html file: /incomplete-ocpp.html
Feb 26 10:12:49 tarragon manager[1634]: 2024-02-26 10:12:49.692563 [INFO] token_provider_  :: Publishing new dummy token: DEADBEEF (RFID)
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.696512 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "SessionStarted"
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.696914 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.743899 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AuthRequired"
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.744326 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:49 tarragon manager[1622]: 2024-02-26 10:12:49.768336 [INFO] auth:Auth        :: Received new token: {
Feb 26 10:12:49 tarragon manager[1622]:     "authorization_type": "RFID",
Feb 26 10:12:49 tarragon manager[1622]:     "id_token": "DEADBEEF"
Feb 26 10:12:49 tarragon manager[1622]: }
Feb 26 10:12:49 tarragon manager[1632]: 2024-02-26 10:12:49.783095 [INFO] tarragon_bsp:Cb  :: Read PP ampacity value: A_32 (U_PP: 1003 mV)
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.818950 [INFO] hmiled:GpioRgbL  :: auth::status_message::token lists no connectors, assuming this event is for us
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.819542 [INFO] hmiled:GpioRgbL  :: Auth validation status: Processing
Feb 26 10:12:49 tarragon manager[1628]: 2024-02-26 10:12:49.833097 [INFO] ocpp:OCPP        :: Found id_tag DEADBEEF in AuthorizationList
Feb 26 10:12:49 tarragon manager[1622]: 2024-02-26 10:12:49.906357 [INFO] auth:Auth        :: Providing authorization to connector#1
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.946460 [INFO] hmiled:GpioRgbL  :: auth::status_message::token lists no connectors, assuming this event is for us
Feb 26 10:12:49 tarragon manager[1627]: 2024-02-26 10:12:49.946875 [INFO] hmiled:GpioRgbL  :: Auth validation status: Accepted
Feb 26 10:12:50 tarragon manager[1622]: 2024-02-26 10:12:50.028955 [INFO] auth:Auth        :: Result for token: DEADBEEF: ACCEPTED
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.095436 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "TransactionStarted"
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.095836 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:50 tarragon manager[1628]: 2024-02-26 10:12:50.098623 [INFO] ocpp:OCPP        :: EVSE#1: Received TransactionStarted
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.142608 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PrepareCharging"
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.143022 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:50 tarragon manager[1632]: 2024-02-26 10:12:50.158692 [INFO] tarragon_bsp:Cb  :: handle_pwm_on: Setting new duty cycle of 26.67%
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.256800 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "ChargingStarted"
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.257188 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:50 tarragon manager[1632]: 2024-02-26 10:12:50.292397 [INFO] tarragon_bsp:Cb  :: Closing contactor...
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.392296 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "ChargingStarted"
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.392686 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:12:50 tarragon manager[1632]: 2024-02-26 10:12:50.395413 [INFO] tarragon_bsp:Cb  :: Contactor state: CLOSED
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.436527 [INFO] hmiled:GpioRgbL  :: Got BSP event "PowerOn"
Feb 26 10:12:50 tarragon manager[1627]: 2024-02-26 10:12:50.436927 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Blue solid
Feb 26 10:13:29 tarragon manager[1628]: 2024-02-26 10:13:29.709531 [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 (2e55de9d-3fea-4782-9b57-2bc027976a31)
Feb 26 10:13:29 tarragon manager[1628]: 2024-02-26 10:13:29.710079 [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 10:14:09 tarragon manager[1628]: 2024-02-26 10:14:09.722098 [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: StartTransaction (941dfb0b-b995-45f5-9833-9dfb3f60dcfb)
Feb 26 10:14:09 tarragon manager[1628]: 2024-02-26 10:14:09.722617 [ERRO] ocpp:OCPP       void ocpp::MessageQueue<M>::handle_timeout_or_callerror(const std::optional<ocpp::EnhancedMessage<M> >&) [with M = ocpp::v16::MessageType] :: Could not deliver message within the configured amount of attempts, dropping message
fec 2188000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
br0: port 1(eth0) entered blocking state
br0: port 1(eth0) entered listening state
br0: port 1(eth0) entered learning state
br0: port 1(eth0) entered forwarding state
Feb 26 10:14:43 tarragon manager[1632]: 2024-02-26 10:14:43.758756 [INFO] tarragon_bsp:Cb  :: CP state change from C to A, U_CP+: 11947 mV, U_CP-: -11318 mV
Feb 26 10:14:43 tarragon manager[1627]: 2024-02-26 10:14:43.791605 [INFO] hmiled:GpioRgbL  :: Got BSP event "A"
Feb 26 10:14:43 tarragon manager[1627]: 2024-02-26 10:14:43.792055 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Blue solid
Feb 26 10:14:43 tarragon manager[1565]: 2024-02-26 10:14:43.800000 [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 10:14:43 tarragon manager[1632]: 2024-02-26 10:14:43.851671 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 10:14:43 tarragon manager[1632]: 2024-02-26 10:14:43.959409 [INFO] tarragon_bsp:Cb  :: Opening contactor...
Feb 26 10:14:43 tarragon manager[1632]: 2024-02-26 10:14:43.998289 [INFO] tarragon_bsp:Cb  :: Contactor state: OPEN
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.033199 [INFO] hmiled:GpioRgbL  :: Got BSP event "PowerOff"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.033653 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.064956 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "StoppingCharging"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.065380 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:14:44 tarragon manager[1632]: 2024-02-26 10:14:44.089580 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.207562 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "ChargingFinished"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.207958 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:14:44 tarragon manager[1628]: 2024-02-26 10:14:44.244802 [INFO] ocpp:OCPP        :: Executing unlock connector callback
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.252544 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "TransactionFinished"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.252975 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Yellow solid
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.309223 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "SessionFinished"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.309661 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1632]: 2024-02-26 10:14:44.337562 [INFO] tarragon_bsp:Cb  :: handle_pwm_off: Setting new duty cycle of 100.00%
Feb 26 10:14:44 tarragon manager[1565]: 2024-02-26 10:14:44.449380 [INFO] manager          :: There are no errors of type evse_manager/MREC4OverCurrentFailure and of module connector->evse, so no errors are cleared
Feb 26 10:14:44 tarragon manager[1623]: 2024-02-26 10:14:44.520288 [INFO] connector:EvseM  :: All errors cleared
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.572722 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PermanentFaultCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.573197 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.605884 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.606288 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1565]: 2024-02-26 10:14:44.621124 [INFO] manager          :: There are no errors of type evse_manager/Internal and of module connector->evse, so no errors are cleared
Feb 26 10:14:44 tarragon manager[1623]: 2024-02-26 10:14:44.689404 [INFO] connector:EvseM  :: All errors cleared
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.718865 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "ErrorCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.719258 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.739601 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.739994 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1565]: 2024-02-26 10:14:44.757962 [INFO] manager          :: There are no errors of type evse_manager/PowermeterTransactionStartFailed and of module connector->evse, so no errors are cleared
Feb 26 10:14:44 tarragon manager[1623]: 2024-02-26 10:14:44.817164 [INFO] connector:EvseM  :: All errors cleared
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.857753 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "PermanentFaultCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.858265 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.889243 [INFO] hmiled:GpioRgbL  :: EvseManager reports session event type "AllErrorsCleared"
Feb 26 10:14:44 tarragon manager[1627]: 2024-02-26 10:14:44.889677 [INFO] hmiled:GpioRgbL  :: GpioLedControl behavior is being set to Green solid
Feb 26 10:14:45 tarragon manager[1633]: 2024-02-26 10:14:45.558822 [INFO] tarragon_pluglo  :: plug is unlocked. Feedback voltage: 3000 mV
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.472676 [ERRO] ocpp:OCPP       ocpp::EnhancedMessage<M> ocpp::MessageQueue<M>::receive(const string&) [with M = ocpp::v16::MessageType; std::string = std::__cxx11::basic_string<char>] :: Received a CALLRESULT OR CALLERROR with mismatching uid: cd52d42c-69f7-4f08-b52d-27dd44516a49 != 2e55de9d-3fea-4782-9b57-2bc027976a31
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.473201 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.476727 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.476563 [ERRO] ocpp:OCPP       void ocpp::v16::ChargePointImpl::message_callback(const string&) :: Received an unsupported message: InternalError
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.881001 [ERRO] ocpp:OCPP       ocpp::EnhancedMessage<M> ocpp::MessageQueue<M>::receive(const string&) [with M = ocpp::v16::MessageType; std::string = std::__cxx11::basic_string<char>] :: Received a CALLRESULT OR CALLERROR with mismatching uid: cd52d42c-69f7-4f08-b52d-27dd44516a49 != 941dfb0b-b995-45f5-9833-9dfb3f60dcfb
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.881427 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.885118 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.884982 [ERRO] ocpp:OCPP       void ocpp::v16::ChargePointImpl::message_callback(const string&) :: Received an unsupported message: InternalError

Pietfried commented 6 months ago

This is indeed not the expected behavior but I'm a little bit surprised because we have actually handling of this use case (start transaction offline, then charger returns online) in place.

Im a little bit confused by this part of the log:

Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.472676 [ERRO] ocpp:OCPP       ocpp::EnhancedMessage<M> ocpp::MessageQueue<M>::receive(const string&) [with M = ocpp::v16::MessageType; std::string = std::__cxx11::basic_string<char>] :: Received a CALLRESULT OR CALLERROR with mismatching uid: cd52d42c-69f7-4f08-b52d-27dd44516a49 != 2e55de9d-3fea-4782-9b57-2bc027976a31
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.473201 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.476727 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.476563 [ERRO] ocpp:OCPP       void ocpp::v16::ChargePointImpl::message_callback(const string&) :: Received an unsupported message: InternalError
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.881001 [ERRO] ocpp:OCPP       ocpp::EnhancedMessage<M> ocpp::MessageQueue<M>::receive(const string&) [with M = ocpp::v16::MessageType; std::string = std::__cxx11::basic_string<char>] :: Received a CALLRESULT OR CALLERROR with mismatching uid: cd52d42c-69f7-4f08-b52d-27dd44516a49 != 941dfb0b-b995-45f5-9833-9dfb3f60dcfb
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.881427 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.885118 [ERRO] ocpp:OCPP       std::string ocpp::v16::conversions::messagetype_to_string(ocpp::v16::MessageType) :: No known string conversion for InternalError MessageType
Feb 26 10:14:46 tarragon manager[1628]: 2024-02-26 10:14:46.884982 [ERRO] ocpp:OCPP       void ocpp::v16::ChargePointImpl::message_callback(const string&) :: Received an unsupported message: InternalError

because it is not represented in the OCPP logs that you shared. Do you have the EVerest OCPP html logs available and are able to share these?

lategoodbye commented 6 months ago

I trimmed the log because i assumed the rest would be irrelevant, here the full OCPP log from Steve:

[INFO ] 2024-02-26 09:10:45,446 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"5c9dcc97-0722-4a3f-9b7b-4da03a402e42","BootNotification",{"chargeBoxSerialNumber":"123","chargePointModel":"Charge Control C","chargePointVendor":"chargebyte","firmwareVersion":"0.5.0"}]
[INFO ] 2024-02-26 09:10:45,448 de.rwth.idsg.steve.service.CentralSystemService16_Service - The boot of the chargebox 'lesbos_left' with registration status 'Optional[ACCEPTED]' is acknowledged.
[INFO ] 2024-02-26 09:10:45,454 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"5c9dcc97-0722-4a3f-9b7b-4da03a402e42",{"status":"Accepted","currentTime":"2024-02-26T09:10:45.448Z","interval":1800}]
[INFO ] 2024-02-26 09:10:45,739 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"a17fc2be-0319-4ae4-91fc-f8525e7d0b8a","StatusNotification",{"connectorId":0,"errorCode":"NoError","status":"Available","timestamp":"2024-02-26T09:10:45.500Z"}]
[INFO ] 2024-02-26 09:10:45,744 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"a17fc2be-0319-4ae4-91fc-f8525e7d0b8a",{}]
[INFO ] 2024-02-26 09:10:45,772 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"67044b36-7b82-4d38-a0c4-7fb308d77549","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T11:36:22.799Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,772 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"67044b36-7b82-4d38-a0c4-7fb308d77549","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,801 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"017c3e5e-1690-4569-bafa-da556d9b27a1","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T11:40:50.789Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,801 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"017c3e5e-1690-4569-bafa-da556d9b27a1","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,816 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"6c4d9636-7c1e-457e-80b0-75585aa6ee29","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T12:47:31.100Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,816 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"6c4d9636-7c1e-457e-80b0-75585aa6ee29","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,829 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"9db53c13-cf75-4211-ba02-233852a7bd8f","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T12:51:10.134Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,829 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"9db53c13-cf75-4211-ba02-233852a7bd8f","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,862 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"062f8b22-0d5b-4672-85f9-c30d26de5853","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T12:51:38.720Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,862 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"062f8b22-0d5b-4672-85f9-c30d26de5853","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,894 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"9e82cdbb-b59a-4eb1-bf64-fe25e2aa0e61","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T13:02:29.790Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,895 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"9e82cdbb-b59a-4eb1-bf64-fe25e2aa0e61","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,921 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"ef9bd9b1-376a-4c34-9268-53ddcb163a89","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T14:07:31.364Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,921 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"ef9bd9b1-376a-4c34-9268-53ddcb163a89","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,955 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"37e59345-268f-4df0-b689-fd5070eb50b4","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T16:01:59.122Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,956 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"37e59345-268f-4df0-b689-fd5070eb50b4","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:45,990 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"c5973901-9089-4587-b91d-81b0b4caf452","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-22T16:13:15.890Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:45,990 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"c5973901-9089-4587-b91d-81b0b4caf452","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,009 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"2db0b6a3-6a5e-4a2b-8a39-e2fe7b372545","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T07:39:25.844Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,010 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"2db0b6a3-6a5e-4a2b-8a39-e2fe7b372545","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,025 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"78e29396-0396-4871-9f21-a75fe2084f9d","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T07:46:58.430Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,025 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"78e29396-0396-4871-9f21-a75fe2084f9d","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,081 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"83456e97-ecb7-4bf2-a339-6c2b16100735","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T07:57:02.869Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,082 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"83456e97-ecb7-4bf2-a339-6c2b16100735","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,104 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"a917a7c1-3e80-4906-9429-f7bcd4f57203","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T07:58:01.260Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,104 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"a917a7c1-3e80-4906-9429-f7bcd4f57203","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,129 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"c6657336-cb5c-4f64-ad9d-c5c69392061c","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T09:02:01.925Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,130 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"c6657336-cb5c-4f64-ad9d-c5c69392061c","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,180 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"06e6836e-04c2-4ab2-9edb-fee032b46d5c","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T09:25:57.780Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,180 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"06e6836e-04c2-4ab2-9edb-fee032b46d5c","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,193 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"540db80a-fa82-4d1c-ae36-d70b48daa4cb","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T09:39:58.199Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,193 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"540db80a-fa82-4d1c-ae36-d70b48daa4cb","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,205 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"18b7f2d7-a165-49b5-a809-cae0b65a7913","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T10:13:41.360Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,206 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"18b7f2d7-a165-49b5-a809-cae0b65a7913","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,226 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"9c01b1ef-16a9-4d8b-b904-b7e679cdd15f","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T10:24:49.233Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,227 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"9c01b1ef-16a9-4d8b-b904-b7e679cdd15f","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,272 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"a7a97ef5-5ca1-4794-9980-a7135fdd9f32","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T10:31:06.935Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,272 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"a7a97ef5-5ca1-4794-9980-a7135fdd9f32","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,298 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"a34adcc5-96fb-4e57-af73-d1aff2e24c77","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T12:30:06.147Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,298 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"a34adcc5-96fb-4e57-af73-d1aff2e24c77","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,314 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"f65f00d7-05f6-4bba-96db-11c79ef6649c","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T14:41:26.335Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,315 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"f65f00d7-05f6-4bba-96db-11c79ef6649c","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,330 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"63100bdf-a195-46cd-92cf-18d348ebd71c","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T14:54:52.010Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,330 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"63100bdf-a195-46cd-92cf-18d348ebd71c","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,359 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"b4e922c5-9b6c-4e81-a5fc-067e0443c3ba","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-23T17:22:55.807Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,359 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"b4e922c5-9b6c-4e81-a5fc-067e0443c3ba","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,372 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"c556c659-55f6-4f1a-9a09-af17859afa50","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-26T09:09:18.980Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,372 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"c556c659-55f6-4f1a-9a09-af17859afa50","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:10:46,383 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"7d022070-28fa-45bd-a121-a756549b1d50","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Available","timestamp":"2024-02-26T09:10:45.505Z"}]
[INFO ] 2024-02-26 09:10:46,388 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"7d022070-28fa-45bd-a121-a756549b1d50",{}]
[INFO ] 2024-02-26 09:10:46,398 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"203c4586-f02a-43d1-9496-06a93a00710b","SecurityEventNotification",{"techInfo":"The Charge Point has booted","timestamp":"2024-02-26T09:10:45.547Z","type":"StartupOfTheDevice"}]
[INFO ] 2024-02-26 09:10:46,399 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [4,"203c4586-f02a-43d1-9496-06a93a00710b","NotImplemented","The action 'SecurityEventNotification' you are looking for is not found",{}]
[INFO ] 2024-02-26 09:14:46,425 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"2e55de9d-3fea-4782-9b57-2bc027976a31","StatusNotification",{"connectorId":1,"errorCode":"NoError","info":"EVConnected","status":"Preparing","timestamp":"2024-02-26T09:12:49.706Z"}]
[INFO ] 2024-02-26 09:14:46,434 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"2e55de9d-3fea-4782-9b57-2bc027976a31",{}]
[INFO ] 2024-02-26 09:14:46,435 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"941dfb0b-b995-45f5-9833-9dfb3f60dcfb","StartTransaction",{"connectorId":1,"idTag":"DEADBEEF","meterStart":971,"timestamp":"2024-02-26T09:12:50.059Z"}]
[INFO ] 2024-02-26 09:14:46,841 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"941dfb0b-b995-45f5-9833-9dfb3f60dcfb",{"transactionId":1458,"idTagInfo":{"status":"Accepted","expiryDate":"2024-02-26T10:14:46.831Z"}}]
[INFO ] 2024-02-26 09:14:46,845 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"cd52d42c-69f7-4f08-b52d-27dd44516a49","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Charging","timestamp":"2024-02-26T09:12:50.265Z"}]
[INFO ] 2024-02-26 09:14:46,850 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"cd52d42c-69f7-4f08-b52d-27dd44516a49",{}]
[INFO ] 2024-02-26 09:14:46,864 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"036b161b-7291-4549-b6ef-5ad88d11b1af","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Finishing","timestamp":"2024-02-26T09:14:44.244Z"}]
[INFO ] 2024-02-26 09:14:46,869 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"036b161b-7291-4549-b6ef-5ad88d11b1af",{}]
[INFO ] 2024-02-26 09:14:46,881 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"5f90e0ca-7ddc-4e66-9cb9-8f9d47b98a3b","StopTransaction",{"meterStop":971,"reason":"EVDisconnected","timestamp":"2024-02-26T09:14:44.157Z","transactionId":-1}]
[ERROR] 2024-02-26 09:14:46,883 de.rwth.idsg.steve.repository.impl.OcppServerRepositoryImpl - Exception occurred
org.jooq.exception.DataAccessException: SQL [insert into `stevedb`.`transaction_stop` (`transaction_pk`, `event_timestamp`, `event_actor`, `stop_timestamp`, `stop_value`, `stop_reason`) values (?, ?, ?, ?, ?, ?)]; Data truncation: Out of range value for column 'transaction_pk' at row 1
    at org.jooq_3.16.7.MYSQL.debug(Unknown Source) ~[?:?]
    at org.jooq.impl.Tools.translate(Tools.java:3095) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:670) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:354) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.AbstractDelegatingQuery.execute(AbstractDelegatingQuery.java:115) ~[jooq-3.16.7.jar:?]
    at de.rwth.idsg.steve.repository.impl.OcppServerRepositoryImpl.updateTransaction(OcppServerRepositoryImpl.java:280) ~[steve.jar:?]
    at de.rwth.idsg.steve.service.CentralSystemService16_Service.stopTransaction(CentralSystemService16_Service.java:221) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.soap.CentralSystemService16_SoapServer.stopTransaction(CentralSystemService16_SoapServer.java:117) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.ocpp16.Ocpp16WebSocketEndpoint$Ocpp16CallHandler.dispatch(Ocpp16WebSocketEndpoint.java:97) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.pipeline.AbstractCallHandler.accept(AbstractCallHandler.java:46) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.pipeline.IncomingPipeline.accept(IncomingPipeline.java:61) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.handleTextMessage(AbstractWebSocketEndpoint.java:117) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.AbstractWebSocketEndpoint.onMessage(AbstractWebSocketEndpoint.java:89) ~[steve.jar:?]
    at de.rwth.idsg.steve.ocpp.ws.ConcurrentWebSocketHandler.handleMessage(ConcurrentWebSocketHandler.java:50) ~[steve.jar:?]
    at org.springframework.web.socket.adapter.jetty.Jetty10WebSocketHandlerAdapter.onWebSocketText(Jetty10WebSocketHandlerAdapter.java:78) ~[spring-websocket-5.3.23.jar:5.3.23]
    at org.eclipse.jetty.websocket.core.internal.messages.StringMessageSink.accept(StringMessageSink.java:53) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.acceptMessage(JettyWebSocketFrameHandler.java:334) ~[websocket-jetty-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onTextFrame(JettyWebSocketFrameHandler.java:407) ~[websocket-jetty-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onFrame(JettyWebSocketFrameHandler.java:240) ~[websocket-jetty-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$IncomingAdaptor.lambda$onFrame$1(WebSocketCoreSession.java:671) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1463) ~[jetty-server-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1482) ~[jetty-server-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker$1.handle(AbstractHandshaker.java:212) ~[websocket-core-server-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$IncomingAdaptor.onFrame(WebSocketCoreSession.java:671) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.ExtensionStack.onFrame(ExtensionStack.java:120) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.onFrame(WebSocketCoreSession.java:481) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onFrame(WebSocketConnection.java:262) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.fillAndParse(WebSocketConnection.java:455) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onFillable(WebSocketConnection.java:340) ~[websocket-core-common-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:319) ~[jetty-io-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) ~[jetty-io-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) ~[jetty-io-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:412) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:381) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:268) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.lambda$new$0(AdaptiveExecutionStrategy.java:138) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:407) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:894) ~[jetty-util-10.0.11.jar:10.0.11]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1038) ~[jetty-util-10.0.11.jar:10.0.11]
    at java.lang.Thread.run(Thread.java:840) ~[?:?]
Caused by: com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Out of range value for column 'transaction_pk' at row 1
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:104) ~[mysql-connector-java-8.0.30.jar:8.0.30]
    at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:555) ~[mysql-connector-java-8.0.30.jar:8.0.30]
    at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:339) ~[mysql-connector-java-8.0.30.jar:8.0.30]
    at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354) ~[mysql-connector-java-8.0.30.jar:8.0.30]
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44) ~[HikariCP-5.0.1.jar:?]
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java) ~[HikariCP-5.0.1.jar:?]
    at org.jooq.tools.jdbc.DefaultPreparedStatement.execute(DefaultPreparedStatement.java:219) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:419) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.AbstractDMLQuery.execute(AbstractDMLQuery.java:961) ~[jooq-3.16.7.jar:?]
    at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:340) ~[jooq-3.16.7.jar:?]
    ... 36 more
[INFO ] 2024-02-26 09:14:46,888 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"5f90e0ca-7ddc-4e66-9cb9-8f9d47b98a3b",{}]
[INFO ] 2024-02-26 09:14:46,995 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"a1815cac-59dd-44eb-8566-14a9568d33d7","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Available","timestamp":"2024-02-26T09:14:44.528Z"}]
[INFO ] 2024-02-26 09:14:46,999 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"a1815cac-59dd-44eb-8566-14a9568d33d7",{}]
[INFO ] 2024-02-26 09:15:00,102 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Received: [2,"03f18431-f271-4b29-9961-17b1a57dfecd","MeterValues",{"connectorId":1,"meterValue":[{"sampledValue":[{"context":"Sample.Clock","format":"Raw","location":"Outlet","measurand":"Energy.Active.Import.Register","unit":"Wh","value":"971.18"}],"timestamp":"2024-02-26T09:14:58.497Z"}]}]
[INFO ] 2024-02-26 09:15:00,110 de.rwth.idsg.steve.ocpp.ws.WebSocketLogger - [chargeBoxId=lesbos_left, sessionId=5863aadf-4995-59e9-1bda-f2c9e09c9e78] Sending: [3,"03f18431-f271-4b29-9961-17b1a57dfecd",{}]

Sorry, the EVerest OCPP html log get lost because of a "systemctl restart everest"?

lategoodbye commented 6 months ago

I also set "DisableSecurityEventNotifications" to true in our OCPP configuration, but the issue is still reproducible.

lategoodbye commented 6 months ago

I was also able to reproduce this issue with EVerest-core 2024.02: see Timestamp 2024-02-29T13:38:25.099Z 2024-02-29T12%3A51%3A36.034Z.zip

Pietfried commented 6 months ago

So far I was not able to reproduce this and the transactionId received by the CSMS when returning online is always used in further messages.

I was also able to reproduce this issue with EVerest-core 2024.02: see Timestamp 2024-02-29T13:38:25.099Z 2024-02-29T12%3A51%3A36.034Z.zip

In your logs it looks like the StartTransaction.conf is never received by the CSMS so that the transactionId is not known. Do you do a complete offline transaction or does the charging station connects to the CSMS again before you do a C -> A ?

lategoodbye commented 6 months ago

The problem with this trace is that it doesn't reflect the reality. The StatusNotification & StartTransaction since 2024-02-29T13:34:27.639Z are send AFTER the controller has been disconnected, because of TCP/IPs nature this take some until the application realize it's offline or online.

Edit: I missed an important detail: HeartbeatInterval is set to 1800 and client-side WebSocketPing is disabled.

Pietfried commented 6 months ago

Ok, thanks for the clarification. In general I would recommend to set the websocket ping so that disconnects can be noticed quicker. Can you always reproduce the transactionId being one or does this only happen sometimes?

lategoodbye commented 6 months ago

In general i agree to use websocket ping, but i also prefer reliable software. Regarding the reproducibility, i don't know the exact circumstances to achieve 100%, but the fault is very stable and not random. So i would say it's easy to reproduce on our platform (80 - 90 % maybe). In case i should investigate this issue deeper, please provide a good starting point (not yet familiar with the EVerest/libocpp code) or some debug instructions.

The -1 transactionId comes from the initialized value of the message? Does the OCPP client has some kind of live dump?

Pietfried commented 6 months ago

Ok, maybe its worth it to have a short meeting about this. Contacted you on Zulip.

Pietfried commented 5 months ago

I was now able to reproduce the issue and opened a PR with a fix: https://github.com/EVerest/libocpp/pull/551

The issue was that the StopTransaction.conf handler could not update the transactionId for future messages, because the transaction_handler could not find the respective transaction. This could occur when EVerest was booting and offline.

EVerest / libocpp