Found the response `callbacks` on `CallbackQueue` are not cleared when client disconnect and reconnected, while the pending request in dispatcher is cleared on disconnect and reconnected.

[dwibudut]

OCPP version: [ ] 1.6 [x] 2.0.1

I'm submitting a ...

[x] bug report [ ] feature request

Current behavior:

Getting call to the obsolete callback even the response is for a new request

Steps to reproduce:

1. CP connected to CSMS
2. After connected, send first message request from CSMS to CP, for example TriggerMessage.req feature:

   [2,"1489738013","TriggerMessage",{"requestedMessage":"StatusNotification"}]

3. Makesure the first message is received by CP
4. Then disconnect the CP without response the TriggerMessage.conf to CSMS
5. After disconnected, reconnect the CP to CSMS.
6. Once connected, send new message request (second message) from CSMS to CP:

   [2,"3052395016","TriggerMessage",{"requestedMessage":"StatusNotification"}]

7. CP received the new message and make the CP to response the TriggerMessage.conf to new/second request (with requestId 3052395016) :

   [3,"3052395016",{"status":"Accepted"}]

8. The result is CSMS getting the response of second message, but call the callback response of requestId 3052395016 is pointing to first/obsolete callback https://github.com/lorenzodonini/ocpp-go/blob/9f716f928b8a0e2bdd1f1b2c563486ec5620fe43/internal/callbackqueue/callbackqueue.go#L40-L62

   The Dequeue method always get the first queued callback even though it is already obsolete (or the first message request callback is still exists).

Full log of test:

time="2024-10-17T13:33:12+07:00" level=debug msg="handling new connection for CP001 from 127.0.0.1:38987"
time="2024-10-17T13:33:14+07:00" level=debug msg="upgraded websocket connection for CP001 from 127.0.0.1:38987"
time="2024-10-17T13:33:18+07:00" level=debug msg="enqueued CALL [1489738013, TriggerMessage] for CP001"
time="2024-10-17T13:33:18+07:00" level=debug msg="queuing data for websocket CP001"
time="2024-10-17T13:33:18+07:00" level=info msg="dispatched request 1489738013 for CP001"
time="2024-10-17T13:33:18+07:00" level=debug msg="sent JSON message to CP001: [2,\"1489738013\",\"TriggerMessage\",{\"requestedMessage\":\"StatusNotification\"}]"
time="2024-10-17T13:33:18+07:00" level=debug msg="started timeout timer for CP001"
time="2024-10-17T13:33:18+07:00" level=debug msg="written 75 bytes to CP001"
time="2024-10-17T13:33:27+07:00" level=debug msg="handling read error for CP001: websocket: close 1000 (normal)"
time="2024-10-17T13:33:27+07:00" level=debug msg="handling forced close signal for CP001"
time="2024-10-17T13:33:27+07:00" level=info msg="closed connection to CP001"
time="2024-10-17T13:33:27+07:00" level=debug msg="timeout canceled for CP001"
time="2024-10-17T13:33:31+07:00" level=debug msg="handling new connection for CP001 from 127.0.0.1:39002"
time="2024-10-17T13:33:31+07:00" level=debug msg="upgraded websocket connection for CP001 from 127.0.0.1:39002"
time="2024-10-17T13:33:35+07:00" level=debug msg="enqueued CALL [3052395016, TriggerMessage] for CP001"
time="2024-10-17T13:33:35+07:00" level=debug msg="queuing data for websocket CP001"
time="2024-10-17T13:33:35+07:00" level=info msg="dispatched request 3052395016 for CP001"
time="2024-10-17T13:33:35+07:00" level=debug msg="sent JSON message to CP001: [2,\"3052395016\",\"TriggerMessage\",{\"requestedMessage\":\"StatusNotification\"}]"
time="2024-10-17T13:33:35+07:00" level=debug msg="started timeout timer for CP001"
time="2024-10-17T13:33:35+07:00" level=debug msg="written 75 bytes to CP001"
time="2024-10-17T13:33:45+07:00" level=debug msg="received JSON message from CP001: [3,\"3052395016\",{\"status\":\"Accepted\"}]"
time="2024-10-17T13:33:45+07:00" level=debug msg="handling incoming CALL RESULT [3052395016] from CP001"
time="2024-10-17T13:33:45+07:00" level=debug msg="completed request 3052395016 for CP001"
time="2024-10-17T13:33:45+07:00" level=debug msg="CP001 ready to transmit again"
time="2024-10-17T13:33:45+07:00" level=debug msg="timeout canceled for CP001"

Other information:

I think it requires a uniqueId/requestId to relate with the callback on CallbackQueue but it looks complicated

cc: @lorenzodonini

[dwibudut]

Hi @lorenzodonini

Just compare the ocpp1.6/central_system.go and ocpp2.0.1/csms.go I found a missed in ocpp2.0.1/csms.go

Here the difference

https://github.com/lorenzodonini/ocpp-go/blob/9f716f928b8a0e2bdd1f1b2c563486ec5620fe43/ocpp1.6/central_system.go#L480-L488

https://github.com/lorenzodonini/ocpp-go/blob/9f716f928b8a0e2bdd1f1b2c563486ec5620fe43/ocpp2.0.1/csms.go#L750-L754

After adding the missed, call callback in CSMS is work normal. That is by Dequeue all pending queue callbacks.

...
func (cs *csms) SetChargingStationDisconnectedHandler(handler ChargingStationConnectionHandler) {
    cs.server.SetDisconnectedClientHandler(func(chargingStation ws.Channel) {
        for cb, ok := cs.callbackQueue.Dequeue(chargingStation.ID()); ok; cb, ok = cs.callbackQueue.Dequeue(chargingStation.ID()) {
            err := ocpp.NewError(ocppj.GenericError, "client disconnected, no response received from client", "")
            cb(nil, err)
        }
        handler(chargingStation)
    })
}
...

I will create a PR to solve this missed.