search

FreeOpcUa / python-opcua

LGPL Pure Python OPC-UA Client and Server
http://freeopcua.github.io/
GNU Lesser General Public License v3.0
1.36k stars 658 forks source link

register OPC UA server to LDS not supported? #1095

Open verschuerenwouter opened 4 years ago

verschuerenwouter commented 4 years ago

hello, I'm trying to register my python OPC UA server tot the OPC foundation local discovery server but keep getting these errors:

Received an error: MessageAbort(error:StatusCode(BadServiceUnsupported), reason:None)
Received an error: MessageAbort(error:StatusCode(BadServiceUnsupported), reason:None)

here is my code:

from opcua import Server, ua
import sys
import time

if __name__ == "__main__":
    server = Server()
    url = "opc.tcp://127.0.0.1:8000"
    server.set_endpoint(url)
    name = "dummy server 2"
    addspace = server.register_namespace(name)

    server.register_to_discovery()

    server.start()

    try:
        while True:
            print("k")
            time.sleep(8)
    except KeyboardInterrupt:
        print("ctr-C has been pressed to shutdown server")    
    finally:
        server.stop()

is this jut not suported or am I doing something wrong?

brubbel commented 4 years ago

Several things:

  1. Your code does not define the location of the OPC foundation LDS. server.register_to_discovery() <- register to where?

  2. What version of the freeopcua library is used? I think the register_to_discovery method was migrated out of the server code some time ago, see: https://github.com/FreeOpcUa/python-opcua/blob/2dca96ea190a661cb1ac1ba0108b46614170f968/tests/tests_server.py#L57-L58

  3. Is this the one you are using? https://opcfoundation.org/developer-tools/samples-and-tools-unified-architecture/local-discovery-server-lds/

oroulet commented 4 years ago

I remember writting that code using spec a few years ago but I have never tested it so you may need to debug it

verschuerenwouter commented 4 years ago
  1. whit the lds running local host for now so i thought i didn't need to define a URL since if left null it auto defines to the LDS def register_to_discovery(self, url="opc.tcp://localhost:4840", period=60):
  2. found out i was using an old library, upgraded, this is my code now but i get the same error [Received an error: MessageAbort(error:StatusCode(BadServiceUnsupported), reason:None)]:
from opcua import Server, ua
from opcua.server.registration_service import RegistrationService

import sys
import time

url = "opc.tcp://127.0.0.1:9097"
urlLDS = "opc.tcp://localhost:4840"
name = "dummy server 2"

if __name__ == "__main__":

    server = Server()
    server.set_endpoint(url)
    addspace = server.register_namespace(name)

    with RegistrationService() as regService:
                    regService.register_to_discovery(server, urlLDS, period=0)
                    time.sleep(0.1)  # let server register registration
    server.start()

    try:
        while True:
            print("k")
            time.sleep(8)
    except KeyboardInterrupt:
        print("ctr-C has been pressed to shutdown server")    
    finally:
        server.stop()

this is the responce of my LDS: 

Thu Jul  9 09:10:20 [6059]: ualds_endpoint_callback called: Event=SecureChannelOpened, SecureChanneldId=0x00000002, uStatus=0x00000000
Thu Jul  9 09:10:20 [6059]: ualds_endpoint_callback: SecureChannel 0x00000002 opened with http://opcfoundation.org/UA/SecurityPolicy#None in mode 1 status 0x00000000!
Thu Jul  9 09:10:20 [6059]: ualds_endpoint_callback called: Event=SecureChannelOpenVerifyCertificate, SecureChanneldId=0x00000002, uStatus=0x800B0000
Thu Jul  9 09:10:20 [6059]: ualds_endpoint_callback: SecureChannel 0x00000002 received request for unsupported service!
Thu Jul  9 09:10:20 [6059]: [uastack] OpcUa_Endpoint_BeginProcessRequest: Not able to create/send response. (0x800B0000)
Thu Jul  9 09:10:20 [6059]: [uastack] OpcUa_SecureListener_ProcessRequest: Closing channel due error 0x800B0000!
  1. i'm using this LDS
swamper123 commented 4 years ago

Sounds like the same problem in #941

SecureChannel 0x00000002 received request for unsupported service! Like @oroulet said, you should try to debug and find out where this message is happening in the code and maybe sniff with a wireshark as well.

Afaik, the LDS requires some security stuff. I've got the feeling that the problem may be around here: https://github.com/FreeOpcUa/python-opcua/blob/bb748c2605dada459f983f492818dbe9a2d114e0/opcua/client/client.py#L126 The LDS shall work with certificates and would need the server certificate in the trust list. Is thast realised?

Have you got an intern log of the LDS as well?

Edit; Is this regestry feature missing in opcua-asyncio or just hidden?

verschuerenwouter commented 4 years ago

even whit the server certificate in the lds's trusted list (and loaded in the server + private key) the error status code stays : BadServiceUnsupported, the full error traceback i get is : 

Received an error: MessageAbort(error:StatusCode(BadServiceUnsupported), reason:None)
Received an error: MessageAbort(error:StatusCode(BadServiceUnsupported), reason:None)
Protocol Error
Traceback (most recent call last):
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/ua_client.py", line 101, in _run
    self._receive()
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/ua_client.py", line 121, in _receive
    self._call_callback(0, ua.UaStatusCodeError(msg.Error.value))
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/ua_client.py", line 131, in _call_callback
    .format(request_id, self._callbackmap.keys())
opcua.ua.uaerrors._base.UaError: No future object found for request: 0, callbacks in list are dict_keys([2])
Traceback (most recent call last):
  File "/home/wouterverschueren/Desktop/dummy server/server 1/server1.py", line 21, in <module>
    regService.register_to_discovery(server,urlLDS, period=60)
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/server/registration_service.py", line 54, in register_to_discovery
    registrationClient.connect()
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/client.py", line 277, in connect
    self.create_session()
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/client.py", line 389, in create_session
    response = self.uaclient.create_session(params)
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/ua_client.py", line 288, in create_session
    data = self._uasocket.send_request(request)
  File "/home/wouterverschueren/.local/lib/python3.6/site-packages/opcua/client/ua_client.py", line 83, in send_request
    data = future.result(self.timeout)
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 430, in result
    raise CancelledError()
concurrent.futures._base.CancelledError

so far i haven't found the intern log of the lds but i don't know if i can acces it

swamper123 commented 4 years ago

@verschuerenwouter I guess it would help, because access tries may be recognised and logged on the lds as well. But this traceback is helpful as well. I haven't got the time today to inspect this deeper, but have a closer look what value self.timeout contains. This (concurrent-)Future object seems to be timedout before it was completed. Maybe, just for fun, add some milli/seconds on it (for science purposes) and try it again:

https://github.com/FreeOpcUa/python-opcua/blob/bb748c2605dada459f983f492818dbe9a2d114e0/opcua/client/ua_client.py#L83

verschuerenwouter commented 4 years ago

@swamper123 are these the logs you were asking for or is it something else?

Thu Jul  9 13:03:21 [5683]: [uastack] OpcUa_SecureListener_ChannelManager_TimerCallback: Checking Channels for lifetime expiration!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Socket_HandleEvent: OPCUA_SOCKET_ACCEPT_EVENT
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Socket(0x55e5608de2f0), Port(4840), Data(0x55e5608d5240), Event(OPCUA_SOCKET_ACCEPT_EVENT)
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Socket(0x55e5608de2f0), Port(4840), Data(0x55e5608d5240), Event(OPCUA_SOCKET_READ_EVENT)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_DataReady: total 56 bytes (48 last) of 48 (w/o header) received.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ReadEventHandler: MessageType HELLO
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ProcessHelloMessage: Transport connection from ::ffff:127.0.0.1:49178 accepted on socket 0x55e5608de2f0!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ConnectionManager_AddConnection: Connection added!
Thu Jul  9 13:03:28 [5683]: [uastack] Requested: PV:0 SB:2147483647 RB:2147483647 MMS:0 MCC:0
Thu Jul  9 13:03:28 [5683]: [uastack] Set:            SB:65536 RB:65536 MMS:16777216 MCC:0
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Flush no. 1 with 0 max flushes and final flag 1!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Messagelength is 28! Last Call!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Buffer emptied!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_OnNotify: Transport Connection Opened
Thu Jul  9 13:03:28 [5683]: [uastack] SecureListener - ChannelManager_AddChannel: SecureChannel added! 0 in list
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Socket(0x55e5608de2f0), Port(4840), Data(0x55e5608d5240), Event(OPCUA_SOCKET_READ_EVENT)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_DataReady: total 132 bytes (124 last) of 124 (w/o header) received.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ReadEventHandler: MessageType SecureChannel Message
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_OnNotify: Request
Thu Jul  9 13:03:28 [5683]: [uastack] SecureStream - CheckInputHeaderType - OpenSecureChannel Service
Thu Jul  9 13:03:28 [5683]: [uastack] ProcessOpenSecureChannelRequest: SID 0, SURI "http://opcfoundation.org/UA/SecurityPolicy#None"
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ChannelManager_GetChannelByTransportConnection: Searched securechannel found!
Thu Jul  9 13:03:28 [5683]: [uastack] SecureListener - PolicyManager_IsValidSecurityPolicy: Searched security policy found!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureStream_AppendInput: Appending buffer 0!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureStream_AppendInput: appended chunk with SN 1, RID 1
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpSecureChannel_GenerateSecurityToken: TOKEN ID is 2-1
Thu Jul  9 13:03:28 [5683]: [uastack] ProcessOpenSecureChannelRequest: Open: Revised Lifetime of Channel 2 from 3600000 to 3600000 ms!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_OnSecureChannelEvent: SecureChannel opened!
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback called: Event=SecureChannelOpened, SecureChanneldId=0x00000002, uStatus=0x00000000
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback: SecureChannel 0x00000002 opened with http://opcfoundation.org/UA/SecurityPolicy#None in mode 1 status 0x00000000!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Flush no. 1 with 0 max flushes and final flag 1!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Messagelength is 135! Last Call!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Buffer emptied!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureStream_Flush: Flush number 0! (Last)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_EndSendResponse: Status 0x00000000
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Socket(0x55e5608de2f0), Port(4840), Data(0x55e5608d5240), Event(OPCUA_SOCKET_READ_EVENT)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_DataReady: total 269 bytes (261 last) of 261 (w/o header) received.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ReadEventHandler: MessageType SecureChannel Message
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_OnNotify: Request
Thu Jul  9 13:03:28 [5683]: [uastack] SecureStream - CheckInputHeaderType - Common Service
Thu Jul  9 13:03:28 [5683]: [uastack] ProcessSessionCallRequest: SID 2, TID 1
Thu Jul  9 13:03:28 [5683]: [uastack] GetSecurityKeyset: Keysets for token id 1 requested.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ProcessSessionCallRequest: All 1 chunks received; start processing!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureStream_AppendInput: Appending buffer 0!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureStream_AppendInput: appended chunk with SN 2, RID 2
Thu Jul  9 13:03:28 [5683]: [uastack] ReleaseSecurityKeyset: Keyset for token 1 released.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_OnNotify: Underlying listener raised request event!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_BeginProcessRequest: Unsupported Service with RequestTypeId 459 requested! (HINT: CreateSessionRequest)
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback called: Event=SecureChannelOpenVerifyCertificate, SecureChanneldId=0x00000002, uStatus=0x800B0000
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback: SecureChannel 0x00000002 received request for unsupported service!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_BeginProcessRequest: Not able to create/send response. (0x800B0000)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_DeleteContext!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ChannelManager_GetChannelByTransportConnection: Searched securechannel found!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ProcessRequest: Closing channel due error 0x800B0000!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_CloseConnection: Connection 0x7f84d40114a0 is being closed! 0x800B0000
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_SendErrorMessage: to ::ffff:127.0.0.1:49178 (socket 0x55e5608de2f0) with StatusCode 0x800B0000
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Flush no. 1 with 0 max flushes and final flag 1!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Messagelength is 16! Last Call!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Buffer emptied!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_P_Socket_Close: Shutting down socket 0x55e5608de2f0!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_Connection_Clear: Done!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ReadEventHandler: Process Request returned an error (0x800B0000)!
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Socket_HandleEvent: OPCUA_SOCKET_CLOSE_EVENT
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Socket(0x55e5608de2f0), Port(4840), Data(0x55e5608d5240), Event(OPCUA_SOCKET_CLOSE_EVENT)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_TimeoutEventHandler: socket 0x55e5608de2f0
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:31 [5683]: [uastack] OpcUa_SecureListener_ChannelManager_TimerCallback: Checking Channels for lifetime expiration!
swamper123 commented 4 years ago

@verschuerenwouter This will help us to understand the issue better. Thanks. At the first glance, this seems to be the important stuff to look at:

Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_OnNotify: Underlying listener raised request event!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_BeginProcessRequest: Unsupported Service with RequestTypeId 459 requested! (HINT: CreateSessionRequest)
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback called: Event=SecureChannelOpenVerifyCertificate, SecureChanneldId=0x00000002, uStatus=0x800B0000
Thu Jul  9 13:03:28 [5683]: ualds_endpoint_callback: SecureChannel 0x00000002 received request for unsupported service!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_BeginProcessRequest: Not able to create/send response. (0x800B0000)
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Endpoint_DeleteContext!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ChannelManager_GetChannelByTransportConnection: Searched securechannel found!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_SecureListener_ProcessRequest: Closing channel due error 0x800B0000!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_CloseConnection: Connection 0x7f84d40114a0 is being closed! 0x800B0000
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_SendErrorMessage: to ::ffff:127.0.0.1:49178 (socket 0x55e5608de2f0) with StatusCode 0x800B0000
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Flush no. 1 with 0 max flushes and final flag 1!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Messagelength is 16! Last Call!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpStream_Flush: Buffer emptied!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_P_Socket_Close: Shutting down socket 0x55e5608de2f0!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_Connection_Clear: Done!
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_TcpListener_ReadEventHandler: Process Request returned an error (0x800B0000)!
Thu Jul  9 13:03:28 [5683]: [uastack]  * OpcUa_TcpListener_EventCallback: Event Handler returned.
Thu Jul  9 13:03:28 [5683]: [uastack] OpcUa_Socket_HandleEvent: OPCUA_SOCKET_CLOSE_EVENT

I will have a closer look in the next days.