@after() handler is causing a deadlock

[HelloWorldo]

Hello,

I'm using this project to implement a Central System to test a (proprietary) Charge Point implementation.
In order to simulate several behaviors, I want to trigger CS initiated requests, but I can't get it to work.

For example, let's imagine you want to trigger a ChangeConfiguration request (from the CS to the CP) after a Heartbeat request (from the CP to the CS).

My naive attempt is to include the following code in the CS sample class (OCPP 1.6). But the execution hangs after the call().
The PDU is sent to the CP, but no further data is received.

@after(Action.Heartbeat)
async def update_heartbeat_interval(self):
	request = call.ChangeConfigurationPayload(
		key="HeartbeatInterval",
		value="123"
	)
	response = await self.call(request)
	#do something with the response...(code never reached)

I'm new to Python, and I don't know if I understand the project architecture or coroutines correctly.
Thanks to all contributors for this project.

[OrangeTux]

Yes, right now it's possible to trigger requests in the @after() handler. However, version v0.3.2 of this package had a bug that prevented that. Which version of the ocpp package are you using?

The fix that was introduced has one drawback: it hides any error that happens during the execution of the handler. So I'm wondering if you suffer of that.

Can you enable debug logs by configuring the log level to debug and print the log? You can do that like this:

import logging
logging.basicConfig(level=logging.DEBUG)

[OrangeTux]

Or do you have an @on() handler registered for the 'Heartbeat'? If not, the @after() handler is not executed.

[HelloWorldo]

I'm using the last version of the ocpp lib from pip (0.7.1)
Yes, I have a @on() registered for 'Hearbeat'

Nothing unusual is seen in the logs:

...
INFO:ocpp:CP_1: receive message [2,"tg03tato4","Heartbeat",{}]
INFO:ocpp:CP_1: send [3,"tg03tato4",{"currentTime":"2020-10-14T08:20:18.961626"}]
INFO:ocpp:CP_1: send [2,"2b50e387-dece-4454-9230-7b2cb9e491f6","ChangeConfiguration",{"key":"HeartbeatInterval","value":"123"}]
<nothing after that>

From the Charge Point's point of view, the ChangeConfiguration packet is received, and a Confirmation is sent.

Here is a complete example of the problem built from the project CS sample:

import asyncio
import websockets
from datetime import datetime

from ocpp.routing import on, after
from ocpp.v16 import ChargePoint as cp
from ocpp.v16.enums import Action, RegistrationStatus
from ocpp.v16 import call_result, call

import logging
logging.basicConfig(level=logging.DEBUG)


class ChargePoint(cp):

    @on(Action.BootNotification)
    def on_boot_notitication(self, charge_point_vendor, charge_point_model, **kwargs):
        return call_result.BootNotificationPayload(
            current_time=datetime.utcnow().isoformat(),
            interval=10,
            status=RegistrationStatus.accepted
        )

    @on(Action.Heartbeat)
    def on_heartbeat(self):
        return call_result.HeartbeatPayload(
            current_time=datetime.utcnow().isoformat(),
        )

    @after(Action.Heartbeat)
    async def update_heartbeat_interval(self):
        request = call.ChangeConfigurationPayload(
            key="HeartbeatInterval",
            value="123"
        )
        response = await self.call(request)
        # do something with the response...(code never reached)
        print(response)


async def on_connect(websocket, path):
    """ For every new charge point that connects, create a ChargePoint instance
    and start listening for messages.

    """
    charge_point_id = path.strip('/')
    cp = ChargePoint(charge_point_id, websocket)

    await cp.start()


async def main():
    server = await websockets.serve(
        on_connect,
        '0.0.0.0',
        9000,
        subprotocols=['ocpp1.6']
    )

    await server.wait_closed()


if __name__ == '__main__':
    asyncio.run(main())

[tropxy]

And can you tell if the ChargePoint received the message and answered to the ChangeConfiguration?

If there is no answer for 30 sec, you will see a timeout error at least

[HelloWorldo]

And can you tell if the ChargePoint received the message and answered to the ChangeConfiguration?

Yes, the Charge Point receives a valid ChangeConfiguration request, and send a valid ChangeConfiguration confirmation (I've double checked it with WireShark). The confirmation doesn't appear on the Central System side.

If there is no answer for 30 sec, you will see a timeout error at least

There is a timeout after 30 sec indeed.

[HelloWorldo]

I want to be sure to not interfere with my own implementation, so I've implemented a complete sample which reproduce the problem, with only the Python library.

The attached files:

• cp.py (the Charge Point)
• csms.py (the Central System)

minimal.zip

Here's what I can observe in the logs, from the CS:

INFO:ocpp:CP_1: receive message [2,"a9651b98-d7f8-4959-aee8-df797473a451","BootNotification",{"chargePointModel":"Optimus","chargePointVendor":"The Mobility House"}]
INFO:ocpp:CP_1: send [3,"a9651b98-d7f8-4959-aee8-df797473a451",{"currentTime":"2020-10-15T07:08:55.158119","interval":10,"status":"Accepted"}]
INFO:ocpp:CP_1: receive message [2,"26004afd-a952-4d00-8ab1-646252a9b1ed","Heartbeat",{}]
INFO:ocpp:CP_1: send [3,"26004afd-a952-4d00-8ab1-646252a9b1ed",{"currentTime":"2020-10-15T07:08:55.170057"}]
INFO:ocpp:CP_1: send [2,"8d45bd6e-6f8e-4516-87c5-f9b66fc4098d","ChangeConfiguration",{"key":"HeartbeatInterval","value":"123"}]

And nothing else (before the timeout occurs).

And from the CP:

INFO:ocpp:CP_1: send [2,"50c35cc3-0d3d-4d05-b372-5cfcd816dbb4","BootNotification",{"chargePointModel":"Optimus","chargePointVendor":"The Mobility House"}]
INFO:ocpp:CP_1: receive message [3,"50c35cc3-0d3d-4d05-b372-5cfcd816dbb4",{"currentTime":"2020-10-15T07:28:48.546510","interval":10,"status":"Accepted"}]
Connected to central system.
INFO:ocpp:CP_1: send [2,"40937f59-ed29-4d79-a4dc-8043a4ee45c2","Heartbeat",{}]
INFO:ocpp:CP_1: receive message [3,"40937f59-ed29-4d79-a4dc-8043a4ee45c2",{"currentTime":"2020-10-15T07:28:48.557482"}]
HeartbeatPayload(current_time='2020-10-15T07:28:48.557482')
INFO:ocpp:CP_1: receive message [2,"6e4fb45b-a5e8-40b8-bd52-81d08bc24c7b","ChangeConfiguration",{"key":"HeartbeatInterval","value":"123"}]
INFO:ocpp:CP_1: send [3,"6e4fb45b-a5e8-40b8-bd52-81d08bc24c7b",{"status":"Accepted"}]

So as with my own implementation, the ChangeConfiguration confirmation is sent and never received on the other side.

I hope somebody could look into it and confirm this behavior.

[OrangeTux]

I can reproduce the problem. The logs of websocket show that the call result is received by the CSMS, but it doesn't seem to make it layer of the ocpp package.

DEBUG:websockets.protocol:server < Frame(fin=True, opcode=1, data=b'[3,"f1b21f7f-fe46-46ae-87d2-40b39ddbb4fe",{"status":"Accepted"}]', rsv1=False, rsv2=False, rsv3=False)

[OrangeTux]

I've founded the problem. I removed by accident this line in the last release.

[HelloWorldo]

It works now, thanks.

[OrangeTux]

I hope to release 0.7.2 containing a fix soon