Subscription leads to NotEnoughData Exception

[roin93]

Hello,

I am subbed to a bunch of nodes on a Siemens SPS.
All Nodes are of node_class Variable.

All my subscriptions are created in a form like this:

# add_subscription will be set when the child is a node of class Variable
# sub_handler is a simple instance of the example SubscriptionHandler shown in almost every example.
if add_subscription and sub_handler is not None:
  # refresh_time is a number, typically something bewteen 100 and 1000
  sub = client.create_subscription(refresh_time, sub_handler)
  # ...
  handle = sub.subscribe_data_change(child)
  # sub and handle will get out of scope in the process. Do i need to save them somewhere or should everything be fine when I have the sub_handler still available in my main function?

I get the following error and currently do not know where I could catch it / how I can get around it.

WARNING:asyncua.server.server:Endpoints other than open requested but private key and certificate are not set.
asyncua.client.ua_client.UaClient:Error parsing notification from server
Traceback (most recent call last):
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/client/ua_client.py", line 486, in publish
    response = struct_from_binary(ua.PublishResponse, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 192, in unpack_uatype
    return extensionobject_from_binary(data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 428, in extensionobject_from_binary
    return from_binary(cls, body)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 199, in unpack_uatype
    return struct_from_binary(cls, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 477, in from_binary
    return unpack_uatype(vtype, data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 188, in unpack_uatype
    return st.unpack(data)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/ua/ua_binary.py", line 127, in unpack
    return struct.unpack(self.format, data.read(self.size))[0]
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/common/utils.py", line 59, in read
    raise NotEnoughData(f"Not enough data left in buffer, request for {size}, we have {self._size}")
asyncua.common.utils.NotEnoughData: Not enough data left in buffer, request for 4, we have 1

Does someone can give me a hint how I could catch this error in my code or do I have to wait for a bugfix?

[roin93]

Maybe this refers to #234 ?

I tried to call
server.load_data_type_definitions() right after the init.
I got the following errors:

[msa_user-m@ms-user opcua_connection]$ python3 main.py
WARNING:asyncio:Executing <Task pending coro=<main() running at main.py:245> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7ff94994e390>()] created at /home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/asyncio/base_events.py:395> cb=[_run_until_complete_cb() at /home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/asyncio/base_events.py:157] created at /home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/asyncio/base_events.py:566> took 2.289 seconds
Traceback (most recent call last):
  File "main.py", line 322, in <module>
    asyncio.run(main(), debug=True)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
    return future.result()
  File "main.py", line 246, in main
    await client.load_data_type_definitions()  # load definition of server specific structures/extension objects
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/client/client.py", line 627, in load_data_type_definitions
    return await load_data_type_definitions(self, node)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/common/structures104.py", line 267, in load_data_type_definitions
    await load_enums(server)  # we need all enums to generate structure code
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/common/structures104.py", line 334, in load_enums
    env = await _generate_object(name, edef, enum=True)
  File "/home/msa_user-m/.conda/envs/opcua_test/lib/python3.7/site-packages/asyncua-0.9.14-py3.7.egg/asyncua/common/structures104.py", line 229, in _generate_object
    exec(code, env)
  File "<string>", line 16
SyntaxError: can't assign to keyword

[oroulet]

can you make sure you use updated master(error seems to show it is an outdated version). Then run a session with wireshark runnning. I need to know what the server tries to send us.

[roin93]

I updated to master right now and installed again via python3 setup.py install.
The error when calling server.load_data_type_definitions() remained the same so I removed the line and tried to subscribe again to a bunch of nodes.
Still getting the NotEnoughData Error:

ERROR:asyncua.client.ua_client.UaClient:Error parsing notification from server
Traceback (most recent call last):
  File "/home/msa_user-m/testing/opcua_connection/asyncua/client/ua_client.py", line 486, in publish
    response = struct_from_binary(ua.PublishResponse, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 192, in unpack_uatype
    return extensionobject_from_binary(data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 428, in extensionobject_from_binary
    return from_binary(cls, body)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 199, in unpack_uatype
    return struct_from_binary(cls, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 477, in from_binary
    return unpack_uatype(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 188, in unpack_uatype
    return st.unpack(data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 127, in unpack
    return struct.unpack(self.format, data.read(self.size))[0]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/common/utils.py", line 59, in read
    raise NotEnoughData(f"Not enough data left in buffer, request for {size}, we have {self._size}")
asyncua.common.utils.NotEnoughData: Not enough data left in buffer, request for 4, we have 1

An output of wireshark will take some time. I do not own admin privileges at the machines and have to wait for an install.

[roin93]

I now tried to subscribe a bunch of nodes from a Beckhoff plc instead of a siemens plc. Same error:

ERROR:asyncua.client.ua_client.UaClient:Error parsing notification from server
Traceback (most recent call last):
  File "/home/msa_user-m/testing/opcua_connection/asyncua/client/ua_client.py", line 486, in publish
    response = struct_from_binary(ua.PublishResponse, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 192, in unpack_uatype
    return extensionobject_from_binary(data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 428, in extensionobject_from_binary
    return from_binary(cls, body)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 480, in from_binary
    return struct_from_binary(uatype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 472, in from_binary
    return unpack_uatype_array(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in unpack_uatype_array
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 224, in <listcomp>
    return [unpack_uatype(vtype, data) for _ in range(length)]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 199, in unpack_uatype
    return struct_from_binary(cls, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 500, in struct_from_binary
    val = from_binary(field.type, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 477, in from_binary
    return unpack_uatype(vtype, data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 188, in unpack_uatype
    return st.unpack(data)
  File "/home/msa_user-m/testing/opcua_connection/asyncua/ua/ua_binary.py", line 127, in unpack
    return struct.unpack(self.format, data.read(self.size))[0]
  File "/home/msa_user-m/testing/opcua_connection/asyncua/common/utils.py", line 59, in read
    raise NotEnoughData(f"Not enough data left in buffer, request for {size}, we have {self._size}")
asyncua.common.utils.NotEnoughData: Not enough data left in buffer, request for 4, we have 1

[roin93]

Can this also refer to python-opcua topic? As I understand the problem was never solved / never given a real solution.

[roin93]

Wireshark output lines 400.000 to 405.000
The error should be present one or two times.
If you tell me how to shrink it down even more I could provide the bigger file, mentioned before. There are several errors in the last 50.000 packages...

script_full_capture_anon_400_405.zip

[oroulet]

oh shit I do not have the netwrok to download that before 1 week.
What I would like to see is the message that the server sent and made us crash. Must be right after we stop answering. Maybe you can add a try/except in your code and call sys.exit() when that error happens? then it will be the last line in the log.
Could you export only the lines around that incident?

[roin93]

One of the incident is around 400.000 to 405.000, that file is around 2MB and uploaded a post before.

I am not sure how to try/except that because that function is called from the server in the background and even after one of the errors my program just adds more subscriptions and the server will be online, just without any (real) call of the datachange_notification function from my SubHandler...

my program is basicly something like this:

class SubHandler(object):
    """
    Subscription Handler. To receive events from server for a subscription
    data_change and event methods are called directly from receiving thread.
    Do not do expensive, slow or network operation there. Create another 
    thread if you need to do such a thing
    """

    def datachange_notification(self, node, val, data):
        print("datachange...")  # I NEVER see this line
        print("Python: New data change event", node, val)
        print(dir(data))
        item = {"node": node, "val": val, "data": data}
        q.put_nowait(item)

async def repeat_calling_function(client, refresh_time, handler, myvar):
    sub = await client.create_subscription(refresh_time, handler)
    handle = await sub.subscribe_data_change(myvar)

async def main():
    logging.basicConfig(level=logging.WARN)
    address = "opc.tcp://192.168.1.3:4840"
    client = Client(address)
    try:
        await client.connect()
        # await client.load_data_type_definitions()  # load definition of server specific structures/extension objects

        # Create sub_handler
        handler = SubHandler()
        refresh_time = 1000  # in milliseconds
        for v in someNodesList:
            await repeat_calling_function(client, refresh_time, handler, v)

        while True:
            await asyncio.sleep(1)

    finally:
        await client.disconnect()

if __name__ == "__main__":
    asyncio.run(main(), debug=True)

Where would i place the mentioned try/except block?

[roin93]

I added a try-except inside of the library at the two points in the common/utils.py file where the Exception is raised.
After that I created a new wireshark file. The main file is around 260MB in size until I got that error.

The last 92 lines (around 0.15 seconds) are in the attached file. If you think you need a few more lines, just tell me.

I would appreciate any kind of suggestion how to handle that problem.

script_full_capture_sys_exit_anon_471900.zip

[roin93]

@oroulet Can you see the cause of the problem from my latest uploads? They are pretty small and I hope you can see the issue there.

[oroulet]

I would like to fix that case, but I do not really know how.... Since the error happens in a custom structure, I would also need to have that custom struct definition here to be able to load it.

one thing that is sure is that load_type_defitinons() and load_enums() have limitations and may end up in that error.

load_data_type_definitions() should work in all cases.
Can you now use load_data_type_definition() using latest master? I think we recently fixed a corner case

If calling that method fails then send me the output here.
If it does not fail. Do you still get the issue?

[roin93]

So I tried the stuff you said.

load_data_type_definitions() should work in all cases.
Can you now use load_data_type_definition() using latest master? I think we recently fixed a corner case

I updated to latest master. Hash is 2dcba36
When I used load_data_type_definitions() as the following:

await client.connect()
await client.load_data_type_definitions()

If calling that method fails then send me the output here.

I got no error message at at this point.

So i let my script run and subscribe all those nodes I subscribed before.

If it does not fail. Do you still get the issue?

It looks like I do not get the error anymore. I get some data_change_notifications with some data in it but I did not see any error as I saw before.
Seems to be already resolved.

I will test it the next few days / next week and if the error occures again I will shout out.
Thanks for the help!