Subscription problem against ignition server about python-opcua HOT 15 CLOSED

can you try to start wireshark, set filter to opcua and send the log when
error happen s? Thanks

On Wed, Sep 16, 2015, 19:16 Jeffrey Price [email protected] wrote:

Hi,
So I'm trying to to subscribe to a node against an OPC UA server hosted by
Ignition (https://inductiveautomation.com/products/ignitionopc/overview)
and I'm getting a problem. I can get nodes, get names, values, and children
from nodes without any problem. But as soon as I try to subscribe to a
node, I get this problem:

exception calling callback for <Future at 0x178e250 state=finished returned Buffer>
Traceback (most recent call last):
File "/opt/osprey/VENV/local/lib/python2.7/site-packages/concurrent/futures/_base.py", line 298, in _invoke_callbacks
callback(self)
File "/opt/python-opcua/opcua/binary_client.py", line 332, in _call_publish_callback
response = ua.PublishResponse.from_binary(future.result())
File "/opt/python-opcua/opcua/uaprotocol_auto.py", line 10443, in from_binary
obj.Parameters = PublishResult.from_binary(data)
File "/opt/python-opcua/opcua/uaprotocol_auto.py", line 10383, in from_binary
obj.SubscriptionId = unpack_uatype('UInt32', data)
File "/opt/python-opcua/opcua/uatypes.py", line 134, in unpack_uatype
return struct.unpack(fmt, data.read(size))[0]
File "/opt/python-opcua/opcua/utils.py", line 39, in read
raise Exception("No enough data left in buffer, request for {}, we have {}".format(size, self))
Exception: No enough data left in buffer, request for 4, we have Buffer(size:0, data:)

After doing some digging, I found:

PublishResponse.from_binary() start:
len(data) at start: 65
len(data) after NodeId: 61
NodeId: NodeId(i=829)
len(data) after ResponseHeader: 37
ResponseHeader: ResponseHeader(Timestamp:2015-09-16 16:03:49.359000, RequestHandle:5, ServiceResult:StatusCode(Good), ServiceDiagnostics:DiagnosticInfo(Encoding:0, SymbolicId:0, NamespaceURI:0, LocalizedText:0, AdditionalInfo:, InnerStatusCode:StatusCode(Good), InnerDiagnosticInfo:None), StringTable:None, AdditionalHeader:ExtensionObject(TypeId:NodeId(i=0), Encoding:0, Body:))
len(data) after PublishResult: 0
Parameters: PublishResult(SubscriptionId:24, AvailableSequenceNumbers:[1], MoreNotifications:True, NotificationMessage:NotificationMessage(SequenceNumber:1, PublishTime:2015-09-16 16:03:49.359000, NotificationData:[]), Results:[], DiagnosticInfos:[])

PublishResponse.from_binary() start:
len(data) at start: 28
len(data) after NodeId: 24
NodeId: NodeId(i=397)
len(data) after ResponseHeader: 0
ResponseHeader: ResponseHeader(Timestamp:2015-09-16 16:03:49.360000, RequestHandle:8, ServiceResult:StatusCode(BadInternalError), ServiceDiagnostics:DiagnosticInfo(Encoding:0, SymbolicId:0, NamespaceURI:0, LocalizedText:0, AdditionalInfo:, InnerStatusCode:StatusCode(Good), InnerDiagnosticInfo:None), StringTable:None, AdditionalHeader:ExtensionObject(TypeId:NodeId(i=0), Encoding:0, Body:))

it's at this point that the error is thrown, as it tries to pull the
PublishResult when the size of data is already at 0. When I get the time, I
want to make a pull request that logs out some of this information and
handles errors a little bit differently.

The error I get from the Ignition console is this:

OPC-UA Server.PublishService Returning ServiceFault for request: [PublishRequest requestHandle=8]. StatusCode=StatusCode[Severity=Bad, Subcode=Bad_InternalError]

java.lang.IllegalArgumentException: fromIndex(0) > toIndex(-1)
at java.util.ArrayList.subListRangeCheck(Unknown Source)
at java.util.ArrayList.subList(Unknown Source)
at com.inductiveautomation.xopc.server.subscriptions.NotificationMessageFactory.createMessageForItems(NotificationMessageFactory.java:118)
at com.inductiveautomation.xopc.server.subscriptions.BaseSubscription.returnNotifications(BaseSubscription.java:583)
at com.inductiveautomation.xopc.server.subscriptions.BaseSubscription.requestReceivedNormal(BaseSubscription.java:453)
at com.inductiveautomation.xopc.server.subscriptions.BaseSubscription.consume(BaseSubscription.java:409)
at com.inductiveautomation.xopc.server.sessions.UaSession.publishRequestReceived(UaSession.java:313)
at com.inductiveautomation.xopc.server.core.services.subscription.PublishService.executeInternal(PublishService.java:38)
at com.inductiveautomation.xopc.server.core.services.subscription.PublishService.executeInternal(PublishService.java:18)
at com.inductiveautomation.xopc.server.core.services.AbstractService.execute(AbstractService.java:53)
at com.inductiveautomation.xopc.server.stack.AbstractUAServer$RequestServer.serveRequest(AbstractUAServer.java:77)
at com.inductiveautomation.xopc.server.stack.AbstractUAServer$RequestServer.run(AbstractUAServer.java:66)
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

This happens very consistently, every time I try to make a subscription.
The code I'm using to make a subscription is based on the example client.
It looks something like this:

import time
from opcua import Client

class SubHandler(object):
"""
Subscription Handler. To receive events from server for a subscription
"""
def data_change(self, handle, node, val, attr):
print("Python: New data change event", handle, node, val, attr)

def event(self, handle, event):
    print("Python: New event", handle, event)

if name == "main":
client = Client("opc.tcp://user:[email protected]:4096/")
try:
client.connect()
var = client.get_node("ns=1;s=[Test_Device]_Meta:Ramp/Ramp4")
print(var)
handler = SubHandler()
sub = client.create_subscription(2000, handler)
handle = sub.subscribe_data_change(var)
time.sleep(0.1)

    i = 0
    timing = 0
    while i < 500:
        print "i:", i
        time.sleep(1)
        i += 1
except Exception as e:
    import traceback
    print traceback.format_exc()
finally:
    client.disconnect()

It gets the node just fine, and I can even get_value() from it, but it
just can't subscribe, so I'm a bit at a loss on how to proceed. Is this
something you have seen? Any suggestions or ideas on how to fix the problem?

—
Reply to this email directly or view it on GitHub
#29.

from python-opcua.

I couldn't figure out how to set the filter, but since the error is easy to reproduce, the log contains very little besides the subscription interaction. How do you want me to send it to you?
Thanks.

from python-opcua.

Send to the list

On Wed, Sep 16, 2015, 20:21 Jeffrey Price [email protected] wrote:

I couldn't figure out how to set the filter, but since the error is easy
to reproduce, the log contains very little besides the subscription
interaction. How do you want me to send it to you?
Thanks.

—
Reply to this email directly or view it on GitHub
#29 (comment)
.

from python-opcua.

Sorry if this is an obvious question, but which list?

from python-opcua.

[email protected]

from python-opcua.

Ah, thank you. It'll be out in a moment.

from python-opcua.

I saw that same error with TOP Server. I think you need to check your "client.get_node" call. If this isn't formatted exactly how the OPC UA server expects it throws exceptions. In fact I had to change the whole thing to look like this because I couldn't "get node" from the client, I had to get it from the root.

 try:
        client.connect()
        root = client.get_root_node()
        print("Root: ", root)
        print("Root children: ", root.get_children())
        print("Browse name: ", root.get_browse_name())
        #var = client.get_node(ua.NodeId(1002, 2))
        # print(var)
        # print(var.get_value())
        #var.set_value(ua.Variant([23], ua.VariantType.Int64))
        state = root.get_child(["0:Objects", "0:Server"])
        print("State: ", state)
        #myvar = root.get_child(["0:Objects", "2:NewObject", "2:MyVariable"])
        #obj = root.get_child(["0:Objects", "2:Functions"])

        #get OPC tag T1
        tempT1 = root.get_child(["0:Objects", "2:SimDriver.Machine.T1"])
        handlerT1 = SubHandler()
        subT1 = client.create_subscription(opcRefreshRate, handlerT1)
        handleT1 = subT1.subscribe_data_change(tempT1)
        time.sleep(0.1)
        #subT1.subscribe_events()

As you can see from what I commented out, in the end I had to call "get_child" from the "root" in order to subscribe. Also the string in the get_child call is very specific. I had to use a OPC UA client called UaExpert in order to figure out what TopServer wanted.

from python-opcua.

Hi,

Any progress here? Here's my problem when subscribing to Ignition:

WARNING:opcua.binary_clientSocket:ServiceFault from server received ServiceFault received from server while waiting for publish response
ERROR:concurrent.futures:exception calling callback for <Future at 0x7fa706764050 state=finished returned Buffer>
Traceback (most recent call last):
  File "/home/nifemi/anaconda/lib/python2.7/site-packages/concurrent/futures/_base.py", line 298, in _invoke_callbacks
    callback(self)
  File "/home/nifemi/anaconda/lib/python2.7/site-packages/opcua/binary_client.py", line 409, in _call_publish_callback
    self._uasocket.check_answer(data, "ServiceFault received from server while waiting for publish response")
  File "/home/nifemi/anaconda/lib/python2.7/site-packages/opcua/binary_client.py", line 71, in check_answer
    hdr.ServiceResult.check()
  File "/home/nifemi/anaconda/lib/python2.7/site-packages/opcua/uatypes.py", line 264, in check
    raise Exception("{}({})".format(self.doc, self.name))
Exception: An internal error occurred as a result of a programming or configuration error.(BadInternalError)

zerox1212's suggestion regarding specific browsing syntax doesnt seem to provide the solution.

from python-opcua.

from python-opcua.

No progress to report other than I tried zerox1212's suggestion to the best of my ability, but without luck. I've had to move on to other things and the project I was doing that this was a problem for got put on the back burner indefinitely.

from python-opcua.

oroulet - Cant do that unfortunately, some confidentiality issues there.

A workaround though - Through tinkering, luck, and a some help from the Ignition devs. The issue seems to be the subscription's MaxNotificationsPerPublish parameter -- it works with a value <= 2147483647.

import time
from opcua import Client, ua
from opcua.subscription import Subscription
import logging
logging.basicConfig()

class SubHandler(object):
    """
    Subscription Handler. To receive events from server for a subscription
    """
    def data_change(self, handle, node, val, attr):
        print("Python: New data change event", handle, node, val, attr)

    def event(self, handle, event):
        print("Python: New event", handle, event)


if __name__ == "__main__":
    client = Client("opc.tcp://localhost:4096") 

    params = ua.CreateSubscriptionParameters()
    params.RequestedPublishingInterval = 2000
    params.RequestedLifetimeCount = 3000
    params.RequestedMaxKeepAliveCount = 10000
    params.MaxNotificationsPerPublish = 2147483647
    params.PublishingEnabled = True
    params.Priority = 0

    try:
        client.connect()

        myvar = client.get_node("ns=2;s=[default]PLC Simulator/Ramp/Ramp9")      
        sub = Subscription(client.bclient, params, SubHandler())
        handle = sub.subscribe_data_change(myvar)
        time.sleep(0.1)

        i = 0
        timing = 0
        while i < 500:
            print "i:", i
            time.sleep(1)
            i += 1
    except Exception as e:
        import traceback
        print traceback.format_exc()
    finally:
        client.disconnect()

You can also set MaxNotificationsPerPublish = 0, and allow the server to choose.

from python-opcua.

0 seems to be not supported by some servers. Maybe we should set it a more reasonable value per default. for example 1000. Any opinion?

from python-opcua.

great debugging work btw!!!

from python-opcua.

Thanks!

I'm not enough of an expert in OPC stuff to suggest a particular default value, but 1000 makes sense to me.

from python-opcua.

change pushed to 3d1b3ab

from python-opcua.