matth-x / MicroOcpp

OCPP 1.6 client for microcontrollers
MIT License
340 stars 149 forks source link

Operation timeout in sending request to Server #251

Open priya2212 opened 9 months ago

priya2212 commented 9 months ago

Dear @matth-x, Hope you are having great weekend. I am having problem with operation timeout in sending request to the OCPP server. When I am testing the same request with Postman, with in 2 sec at max, I receive the response. But with esp32-s3 as client, facing operation timeout for Idtag Authorize, also I don't see the auth request has been created to send to OCPP server. Here are the logs for reference -

`[MO] Send: [2,"1000000","BootNotification",{"chargePointModel":"ESP-IDF charger","chargePointVendor":"Your brand name here"}] [MO] Recv: [3,"1000000",{"status":"Accepted","currentTime":"2024-01-20T21:01:50.9618862+00:00","interval":300}]

[MO] info (BootNotification.cpp:81): request has been Accepted [MO] info (StatusNotification.cpp:50): New status: Available (connectorId 0) [MO] info (StatusNotification.cpp:50): New status: Preparing (connectorId 1) [MO] info (StatusNotification.cpp:50): New status: Available (connectorId 2) [MO] info (SmartChargingService.cpp:509): New limit for connector 1, scheduled at = 2024-01-20T21:01:54.971Z, nextChange = 2037-01-01T00:00:00.000Z, limit = {-1.000000,-1.000000,-1} [MO] Send: [2,"1000001","StatusNotification",{"connectorId":0,"errorCode":"NoError","status":"Available","timestamp":"2024-01-20T21:01:50.961Z"}] [MO] Recv: [3,"1000001",{}] [MO] Send: [2,"1000002","StatusNotification",{"connectorId":1,"errorCode":"NoError","status":"Preparing","timestamp":"2024-01-20T21:01:52.971Z"}] [MO] Recv: [3,"1000002",{}] [MO] Send: [2,"1000003","StatusNotification",{"connectorId":2,"errorCode":"NoError","status":"Available","timestamp":"2024-01-20T21:01:54.971Z"}] [MO] Recv: [3,"1000003",{}] [MO] Send: [2,"1000004","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-01-20T21:02:26.041Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] info (RequestQueue.cpp:45): operation timeout: Authorize [MO] Recv: [3,"1000004",{}] [MO] Send: [2,"1000005","MeterValues",{"connectorId":2,"meterValue":[{"timestamp":"2024-01-20T21:02:26.041Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] Recv: [3,"1000005",{}] [MO] Send: [2,"1000007","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-01-20T21:03:30.201Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] info (RequestQueue.cpp:45): operation timeout: Authorize [MO] Recv: [3,"1000007",{}] [MO] Send: [2,"1000008","MeterValues",{"connectorId":2,"meterValue":[{"timestamp":"2024-01-20T21:03:30.201Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] info (RequestQueue.cpp:45): operation timeout: MeterValues [MO] Send: [2,"1000010","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-01-20T21:04:35.331Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] Recv: [3,"1000008",{}] [MO] warning (RequestQueue.cpp:247): Received response doesn't match any pending operation [MO] Recv: [3,"1000010",{}] [MO] Send: [2,"1000011","MeterValues",{"connectorId":2,"meterValue":[{"timestamp":"2024-01-20T21:04:35.331Z","sampledValue":[{"value":"42.0","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Periodic","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}] [MO] info (RequestQueue.cpp:45): operation timeout: MeterValues [MO] Send: [2,"1000012","MeterValues",{"connectorId":1,"meterValue":[{"timestamp":"2024-01-20T21:05:01.441Z","sampledValue":[{"value":"42.0","context":"Sample.Clock","measurand":"Energy.Active.Import.Register","unit":"V"},{"value":" 1.2","context":"Sample.Clock","measurand":"Energy.Active.Import.Register","unit":"A"},{"value":" 1.2","context":"Sample.Clock","measurand":"Energy.Active.Import.Register","unit":"Wh"}]}]}]`

Would really appreciate your valuable insights. Please let me know if I need to provide any code details, would be happy to share. Thanks in advance.

matth-x commented 9 months ago

The logs indicate a connectivity issue. Is the ESP able to maintain a robust WebSocket connection? In case it isn't, then these timeouts are normal and expected behavior, although the user experience will suffer of course.

My advice would be to sort out the connectivity issues with the WebSocket client only. The OCPP lib somewhat obfuscates the behavior of the underlying networking technology which can cause headaches when debugging. An isolated test setup requires no OCPP traffic, just create a WebSocket connection to the server and check if it remains alive by sending WebSocket pings. SteVe won't drop clients without any traffic.

Maybe the looks reveal some more details if you increase the verbosity to MO_DL_DEBUG. It can be changed in the main platformio.ini manifest, for example like this:

https://github.com/matth-x/MicroOcpp/blob/12d4868200d9675d98ff81b9c226e5deace64c12/platformio.ini#L22

priya2212 commented 9 months ago

I tested it and the separate test with OCPP traffic is working completely fine. But when sending Meter values and IDtag in OCPP during transaction, it is giving operation timeout. I have increased the log level but I don't see any instability there. Code snippet details are attached in this ticket - https://github.com/matth-x/MicroOcpp/issues/225

Framework used - ESP-IDF

ap9389552 commented 1 week ago

Can i get your reference code actually Im not able to send meter value to CMS