OCPP message logging can be out of order

[james-ctc]

OCPP Version

OCPP1.6, OCPP2.0.1

Describe the bug

OCPP states that only one message should be sent at a time.

send MeterValues.req -> sent
send DataTransfer.req -> queued
receive MeterValues.conf
DataTransfer.req -> sent

However in the journalctl log (and OCPP logs) the following is observed:

2025-05-16T11:15:00.053Z: ChargePoint>CentralSystem MeterValues 
[
  2,
  "e6ccb988-0a65-4b0d-97d3-bc40734ed67e",
  "MeterValues",
  {
...
  }
]

2025-05-16T11:15:05.158Z: ChargePoint>CentralSystem DataTransfer 
[
  2,
  "602da2b8-c4d3-4c71-a226-166d27036240",
  "DataTransfer",
  {
...
  }
]

2025-05-16T11:15:05.173Z: CentralSystem>ChargePoint  MeterValuesResponse
[
  3,
  "e6ccb988-0a65-4b0d-97d3-bc40734ed67e",
  {}
]

2025-05-16T11:15:05.201Z: CentralSystem>ChargePoint  DataTransferResponse
[
  3,
  "602da2b8-c4d3-4c71-a226-166d27036240",
  {
    "status": "Accepted"
  }
]

The CSMS logs (UTC+1)

2025-05-16 12:15:00,088 - everest.ocpp - INFO - Rx: [2,"e6ccb988-0a65-4b0d-97d3-bc40734ed67e","MeterValues",{"connectorId":1,"meterValue":[...],"timestamp":"2025-05-16T11:14:59.131Z"}],"transactionId":59801}]
2025-05-16 12:15:05,097 - everest.ocpp - INFO - Tx: [3,"e6ccb988-0a65-4b0d-97d3-bc40734ed67e",{}]
2025-05-16 12:15:05,170 - everest.ocpp - INFO - Rx: [2,"602da2b8-c4d3-4c71-a226-166d27036240","DataTransfer",{...}] 
2025-05-16 12:15:05,171 - everest.ocpp - INFO - Tx: [3,"602da2b8-c4d3-4c71-a226-166d27036240",{"status":"Accepted"}]

The EVerest logs do not reflect the order that the messages were sent/received.

To Reproduce

Run EVerest with a charging session that generates MeterValues and have a module generate DataTransfer messages that are to be send at a similar time to the MeterValues message.
Observe the EVerest logs compared to the CSMS logs (or wireshark)

Anything else?

Logging for sent messages is done in Websocket::send() from the MessageQueue.
Received messages are processed in the MessageQueue (to wait for the conf message before sending the next request) however they are not logged there.
Logging for received messages is in ChargePointImpl::message_callback()
It is possible that moving received message logging into the MessageQueue code should help ensure the accuracy of the log.

This was observed and tested on OCPP 1.6 however the MessageQueue is common code.

[mlitre]

Quick update: I looked into the issue and there are two reasons we are encountering the problem today. The first is that we use the enhanced message type to be able to log, which means that we pass by the message queue before logging. The second is that we do not pass the logging object to the message queue so we cannot log it earlier there.
The two possible solutions would be to log earlier in the message_callback without using the enhanced message (this should be possible we just need to extract the message type string, might be harder in a call result / error) or to pass the logging object to the message queue.