Error: ServiceFault from server received while waiting for publish response on Debian Jessie

[JohannesMaier]

Hello, I worked with following Code on Windows 10 with python 3.6.5 and uaGate from Softing as OPCUA-Server. Everything worked fine untill i runned same code on Debian Jessie with Python 3.5.3:

from opcua import Client, ua
import threading
import signal
import atexit

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):
        #start routine now:
        start_new_thread(datachange_notification_routine,(self, node, val, data))

    def event_notification(self, event):
        pass

def datachange_notification_routine(self, node, val, data): 
    if node == node1:
        print("Event 1")
    elif node == node2: 
        print("Event 2")

def connect():
    global client
    client = Client("opc.tcp://192.168.61.2:4840/")

    #Set certificate
    client.load_client_certificate("my_cert.pem")
    client.load_private_key("my_private_key.pem")

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

    try:
        client.connect()
        client.open_secure_channel(True)

        root = client.get_root_node()

        node1 = root.get_child(["0:Objects", "2:S7", "2:S7.publicVariables", "2:S7.publicVariables.node1"])
        node2 = root.get_child(["0:Objects", "2:S7", "2:S7.publicVariables", "2:S7.publicVariables.node2"])

        handler1 = SubHandler()
        handler2 = SubHandler()
        sub1 = client.create_subscription(50, handler1)
        sub2 = client.create_subscription(50, handler2)        
        handle1 = sub1.subscribe_data_change(node1)
        time.sleep(0.1)
        handle2 = sub2.subscribe_data_change(node2)
        time.sleep(0.1)

    except:
        disconnect()

def handle_exit():
    sub1.unsubscribe(handle1)
    sub1.delete()
    sub2.unsubscribe(handle2)
    sub2.delete()

atexit.register(handle_exit)
signal.signal(signal.SIGTERM, handle_exit)
signal.signal(signal.SIGINT, handle_exit)

Now I get following Error:

ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable

The problem is that the error doesn´t seem to occure synchron with any events. It seems to occure pretty much haphazard. Since I don´t want to go back to Win10, does anyone know how to solve this on Jessie.

Thanks & kind regards Johannes

[oroulet]

Can you paste the complete error log. Some info is missing here

[JohannesMaier]

Hi oroulet,

Can you paste the complete error log. Some info is missing here

Unfortunately it´s everything I get.

Furthermore, the parts with ServiceFault from server received while waiting for publish response and

Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable

are occuring over and over. Partly I get them more than once in row.

[oroulet]

Somewhere there should be a explanation of what service fault.

[JohannesMaier]

Do you know where I can find more details about this service fault?

[zerox1212]

I think he means you need to look in the OPC UA spec document.

[JohannesMaier]

@zerox1212 I already looked for this error but can´t find any working solutions.

Furthermore I think that the service fault is not that critical as the second error. "TypeError: 'NoneType' object is not iterable" sounds more critical for me, even more I can´t find any infos about that in the web.

[oroulet]

The problem is the service fault we received from server. As long as we do not know what for it is we cannot do much. Try to use Wireshark and if you get an error stop immediately the recording and send us the file

[oroulet]

Alternatively you can find out where in the code the error fault is catched and print it. It should already be printed so something is wrong around that line

[JohannesMaier]

Hi oroulet, now I have the tshark log from the service fault: tshark.log

...and the whole output of the opcua server:

ServiceFault from server received while waiting for publish response
exception calling callback for <Future at 0x7fe919408f28 state=finished returned Buffer>
Traceback (most recent call last):
  File "/usr/lib/python3.5/concurrent/futures/_base.py", line 297, in _invoke_callbacks
    callback(self)
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 433, in _call_publish_callback
    self._uasocket.check_answer(data, "while waiting for publish response")
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 87, in check_answer
    hdr.ServiceResult.check()
  File "/usr/local/lib/python3.5/dist-packages/opcua/ua/uatypes.py", line 235, in check
    raise UaStatusCodeError(self.value)
opcua.ua.uaerrors._auto.BadTooManyPublishRequests: The server has reached the maximum number of queued publish requests.(BadTooManyPublishRequests)
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response

ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable
ServiceFault from server received while waiting for publish response
ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable
ServiceFault from server received while waiting for publish response
Exception while calling user callback: %s
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/opcua/client/ua_client.py", line 475, in _call_publish_callback
    callback(response.Parameters)
  File "/usr/local/lib/python3.5/dist-packages/opcua/common/subscription.py", line 109, in publish_callback
    for notif in publishresult.NotificationMessage.NotificationData:
TypeError: 'NoneType' object is not iterable

[oroulet]

Thanks. Then this is the bug we fixed last week. Can you update to last version using pip then try again? Pip install opcua --upgrade

[JohannesMaier]

Thanks for this suggestion and bugfixing! I executed "pip3 install opcua --upgrade", but got the message that I already have the current version (0.95.1).

Is this update only available on Python2?

[oroulet]

Should be 0.98.3. You have an issue on your PC. Should support both 2 an 3

[JohannesMaier]

I tried this: root@server:/home/user1# pip3 install opcua --upgrade and got this:

Requirement already up-to-date: opcua in /usr/local/lib/python3.5/dist-packages
Requirement already up-to-date: pytz in /usr/local/lib/python3.5/dist-packages (from opcua)
Requirement already up-to-date: lxml in /usr/local/lib/python3.5/dist-packages (from opcua)
Requirement already up-to-date: python-dateutil in /usr/local/lib/python3.5/dist-packages (from opcua)
Requirement already up-to-date: six>=1.5 in /usr/lib/python3/dist-packages (from python-dateutil->opcua)

Is there an other way to excecute the update?

[oroulet]

Most probably you have opcua installed several places and running the old one. Try with --user as a hack

[JohannesMaier]

With option --user it doesn´t worked too. So I uninstalled the bib and installed it new. After this I had version 0.98.3 as you said. Aaaand it seems to work now! I will excecute further test, but for now I am good with it. Great Troubleshooting! Thanks @oroulet !

[JohannesMaier]

After further (longer) tests, I recongnized that the error is still occurring and it´s still the same. So I guess that the update was not the solution. @oroulet Do you have another suggested solution.

[MagnusWestin]

I have a similar problem, or at least it I get the same error in the log. What happens is that after a while I don't get notifications any more. I made a fix for it. Basically added a try statement around the for loop in subscription.py:publish_callback. Its to trap when NotificationMessage or NotificationData is None. That way the code still runs the subscription acknowledgement part. For me it seems to solve the issue with not receiving notifications after a while. I'm testing the code right now. And was thinking of preparing a pull request. It will be my first on github... so it might take a while :)

Here is the relevant part of the log

2018-09-13 10:44:10,575   ERROR    Exception while calling user callback: %s 
Traceback (most recent call last):
   File "/usr/lib/python2.7/site-packages/opcua/client/ua_client.py", line 483, in _call_publish_callback
   callback(response.Parameters)   File "/usr/lib/python2.7/site-packages/opcua/common/subscription.py", line 107, in publish_callback
   for notif in publishresult.NotificationMessage.NotificationData: TypeError: 'NoneType' object is not iterable 

[oroulet]

We sold fix handling of that particular error. But antsy it is the consequence of another one. Don't you have other errors in stack trace?

[MagnusWestin]

No, thats the only error. And I'm running version 0.98.5. I've been testing over the weekend. And its completely stable after I fixed the exception in publish_callback.

[oroulet]

Can you send a PR? Just add a test

[MagnusWestin]

Working on it. I've not been in the office the last couple of days. One question, I just added try except around the code. Another solution would be to check for None. Which solution would be preferable?

[oroulet]

if xx is not None: is the correct way to test for that kind of things. try/catch does cost if an error is raised

[oroulet]

looking at it now... there is something very strange here.. NotificationData is initialized to []...how is it transformed to None......?

[oroulet]

OK , just add the test. but there is another parsing issue here somewhere. Could you record a session with wireshark when this happen? how does the notification looks like? a notification without any data?

[MagnusWestin]

I have a fix that is tested now. But some questions, I can't seem to create a branch, which would be needed to do the pull request.

Also, I checked the existing code for testing subscriptions and I can't figure out a way to force it to fail with NotificationData as None. Any tips would be appreciated. Please note that I'm not that proficient with Python :) its not my normal programming language.

I'll try to get some wireshark logs for you.

[zerox1212]

Are you trying to branch from this repo? You should make your own fork of this repo, branch your own repo, then make a PR back into this repo.

[MagnusWestin]

Thanks for the tip, I've never really used github that much before. I've created a PR now.

[MagnusWestin]

@JohannesMaier My fix has been accepted and it solves my issue, that seems to be similar to yours. You might want to try the latest code to see if this also solves it for you.