Ignoring response with unknown unique id

[iandresolares]

Hello, I have been working with the library for a while now, also I have tried it with different ChargePoints from different brands and I have to say good work and thank you!

However now, I am facing a problem which I hadn't seen before with any other chargers. I am working on the Central System side, when sending a "SetChargingProfile" request on an ongoing transaction I get the following:

SN10052201126263: send [2,"12505155-afc5-4b55-bc8a-4e88151cec37","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":7370,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Absolute","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":8.6}]}}}]
Ignoring response with unknown unique id: <CallResult - unique_id=ff80ff4a-c1b6-41b0-bcb8-efde1f6c902b, action=None, payload={'status': 'Accepted'}>

As you can see the conf id is different than the request id, this does not happen with other requests, and the profile is set correctly. Is this a problem of the ChargePoint itself?

Thank you for your time!

[OrangeTux]

Hello @iandresolares,

Good to hear that this library is useful for you. Can you provide full logs that contain all the messages that has been send and received?

[iandresolares]

Oh I see the problem now, I think what is happening is that, the Charge Point doesn't answer in time sometimes after the SetChargingProfile request has been sent and then the TimeOutError raises. As you can see here, The first SetChargingProfile is responded correctly however afterwords there is an exception (before I am not sure why I wasn't getting this exception, I probably messed up and hid it somehow).

SN10052201126263: receive message [2,"306","Authorize",{"idTag":"ec734164"}]
SN10052201126263: send [3,"306",{"idTagInfo":{"status":"Accepted"}}]
SN10052201126263: receive message [2,"307","StartTransaction",{"connectorId":1,"idTag":"ec734164","meterStart":354,"timestamp":"2022-02-01T15:45:14Z"}]
SN10052201126263: send [3,"307",{"transactionId":3874,"idTagInfo":{"status":"Accepted"}}]
SN10052201126263: receive message [2,"308","StatusNotification",{"connectorId":1,"status":"Charging","errorCode":"NoError","timestamp":"2022-02-01T15:45:16Z","vendorId":"EN+","info":"{\"reason\":\"plugInGun\",\"cpv\":0,\"rv\":0}","vendorErrorCode":"00000000000000000000000004000000"}]
SN10052201126263: send [3,"308",{}]
SN10052201126263: receive message [2,"309","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2022-02-01T15:45:17+00:00","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Sample.Periodic"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"0.1"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"0.1","context":"Sample.Periodic"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"354.0","context":"Sample.Periodic"},{"measurand":"Power.Active.Import","unit":"W","value":"0.0","context":"Sample.Periodic"}]}],"transactionId":3874}]
SN10052201126263: send [3,"309",{}]
SN10052201126263: send [2,"0ae388c7-18b8-4956-a017-34fdf26fe9ff","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":9453,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Absolute","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":8.6}]}}}]
SN10052201126263: receive message [3,"0ae388c7-18b8-4956-a017-34fdf26fe9ff",{"status":"Accepted"}]
SN10052201126263: receive message [2,"310","Heartbeat",{}]
SN10052201126263: send [3,"310",{"currentTime":"2022-02-01T15:45:29.332632+01:00"}]
SN10052201126263: receive message [2,"311","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2022-02-01T15:45:39+00:00","sampledValue":[{"measurand":"Current.Offered","unit":"A","value":"32.0","context":"Sample.Periodic"},{"measurand":"Current.Import","unit":"A","phase":"L1","value":"3.5"},{"measurand":"Voltage","unit":"V","phase":"L1","value":"232.4","context":"Sample.Periodic"},{"measurand":"Energy.Active.Import.Register","unit":"Wh","value":"358.0","context":"Sample.Periodic"},{"measurand":"Power.Active.Import","unit":"W","value":"820.0","context":"Sample.Periodic"}]}],"transactionId":3874}]
SN10052201126263: send [2,"ac0b3c35-405c-473c-85d3-94726b8e3a9e","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":7271,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Absolute","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":12.2}]}}}]
SN10052201126263: send [2,"0ca11def-2ed6-418a-9207-bf050a05f09a","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":7971,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Absolute","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":8.6}]}}}]
Error while handling request '<Call - unique_id=311, action=MeterValues, payload={'connectorId': 1, 'meterValue': [{'timestamp': '2022-02-01T15:45:39+00:00', 'sampledValue': [{'measurand': 'Current.Offered', 'unit': 'A', 'value': '32.0', 'context': 'Sample.Periodic'}, {'measurand': 'Current.Import', 'unit': 'A', 'phase': 'L1', 'value': '3.5'}, {'measurand': 'Voltage', 'unit': 'V', 'phase': 'L1', 'value': '232.4', 'context': 'Sample.Periodic'}, {'measurand': 'Energy.Active.Import.Register', 'unit': 'Wh', 'value': '358.0', 'context': 'Sample.Periodic'}, {'measurand': 'Power.Active.Import', 'unit': 'W', 'value': '820.0', 'context': 'Sample.Periodic'}]}], 'transactionId': 3874}>'
Traceback (most recent call last):
  File "C:\Users\sydea\AppData\Local\Programs\Python\Python39-32\lib\asyncio\queues.py", line 166, in get
    await getter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\sydea\AppData\Local\Programs\Python\Python39-32\lib\asyncio\tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "C:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\venv\lib\site-packages\ocpp\charge_point.py", line 270, in call
    await self._get_specific_response(call.unique_id,
  File "C:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\venv\lib\site-packages\ocpp\charge_point.py", line 303, in _get_specific_response
    response = await asyncio.wait_for(self._response_queue.get(),
  File "C:\Users\sydea\AppData\Local\Programs\Python\Python39-32\lib\asyncio\tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\venv\lib\site-packages\ocpp\charge_point.py", line 192, in _handle_call
    response = await response
  File "c:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\src\chargepoints\business_charge_point.py", line 344, in on_meter_values
    await self.master.load_balancing_strategy()
  File "c:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\src\chargepoints\business_charge_point.py", line 181, in fifo_load_balancing
    return await asyncio.gather(*load_balancing_tasks_list)
  File "c:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\src\chargepoints\abstract_charge_point.py", line 249, in set_charging_profile
    return await self.call(
  File "C:\Users\sydea\Desktop\Cargadores solares\Proyecto\ocpp-central-system\venv\lib\site-packages\ocpp\charge_point.py", line 273, in call
    raise asyncio.TimeoutError(
asyncio.exceptions.TimeoutError: Waited 30s for response on [2,"ac0b3c35-405c-473c-85d3-94726b8e3a9e","SetChargingProfile",{"connectorId":1,"csChargingProfiles":{"chargingProfileId":7271,"stackLevel":0,"chargingProfilePurpose":"TxProfile","chargingProfileKind":"Absolute","chargingSchedule":{"chargingRateUnit":"A","chargingSchedulePeriod":[{"startPeriod":0,"limit":12.2}]}}}].
SN10052201126263: send [4,"311","InternalError","An unexpected error occurred.",{}]
SN10052201126263: receive message [3,"ac0b3c35-405c-473c-85d3-94726b8e3a9e",{"status":"Accepted"}]
SN10052201126263: receive message [2,"312","Heartbeat",{}]
SN10052201126263: send [3,"312",{"currentTime":"2022-02-01T15:46:09.879818+01:00"}]
SN10052201126263: receive message [2,"313","Heartbeat",{}]
SN10052201126263: send [3,"313",{"currentTime":"2022-02-01T15:46:09.881351+01:00"}]
Ignoring response with unknown unique id: <CallResult - unique_id=ac0b3c35-405c-473c-85d3-94726b8e3a9e, action=None, payload={'status': 'Accepted'}>
SN10052201126263: receive message [3,"0ca11def-2ed6-418a-9207-bf050a05f09a",{"status":"Accepted"}]

I have also tried with a charger from a different brand and also occurs now. The only thing I can think of I changed that could influence that I increased the frequency of SetChargingProfile requests (to around once every 90 seconds). For now I have solved it by chaging the response_timeout instance attribute of ChargePoint class to 60 seconds, but I find weird that the ChargePoint is not answering within the default 30 seconds. Do you think this could be because of the frequency of the SetChargingProfile requests I am using? Maybe the Charge Point can't keep up or something like that.

Let me know if you have any suggestions on what could be going on. Thank you!!

[susanthomasv]

How do we get this log as sent and received messages?

[iandresolares]

How do we get this log as sent and received messages?

Add this to your script:

import logging
logging.getLogger("ocpp").setLevel(level=logging.DEBUG)
logging.getLogger("ocpp").addHandler(logging.StreamHandler())

[susanthomasv]

Thank you. Can we store the data coming from log into a variable?

[iandresolares]

coming fro

Thank you. Can we store the data coming from log into a variable?

That's weird but I guess it can be done with a custom formatter or something like that

[deepakEnercent]

Did anyone find any resolution? even I am waiting for 100 seconds (which is not good I know) for testing. still, it gets time out and this kind of message shows up..

[Jared-Newell-Mobility]

Referring to OCPP 1.6 - When sending multiple charging profiles the charge point SHALL then re-evaluate its collection of charge profiles to determine which charging profile will become active. This may not be handled well by the charge point, however, only the logs of the charge point will show this. It maybe possible to implement a Get Diagnostics message to understand the charge points side of the story. Although, message flow appears to be ordered which is positive.