opcua icon indicating copy to clipboard operation
opcua copied to clipboard

Is there anything wrong ?

Open flykarry opened this issue 3 years ago • 6 comments

I Connect to the server and read something, then wait sometime about 5 minute ,the nrerun the read method, and the client will stuck reconnecting

debug: uacp: connecting to opc.tcp://127.0.0.1:49320
debug: uacp 1: start HEL/ACK handshake
debug: uacp 1: sent HELF with 57 bytes
debug: uacp 1: recv ACKF with 28 bytes
debug: uacp 1: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x1000000, MaxChunkCount:0x1388}
debug: uasc 1/1: send *ua.OpenSecureChannelRequest with 132 bytes
debug: uacp 1: recv OPNF with 135 bytes
debug: uasc 1/1: recv OPNF with 135 bytes
debug: uasc 1/1: recv *ua.OpenSecureChannelResponse
debug: uasc 1/1: sending *ua.OpenSecureChannelResponse to handler
debug: uasc 1: received security token. channelID=4118070434 tokenID=1 createdAt=2022-02-18T08:24:43Z lifetime=1h0m0s
debug: uasc 1: security token expires at 2022-02-18T09:39:43Z. channelID=4118070434 tokenID=1
debug: uasc 1: security token is refreshed at 2022-02-18T09:09:43Z (45m0s). channelID=4118070434 tokenID=1
debug: uasc 1/2: send *ua.GetEndpointsRequest with 94 bytes
debug: uacp 1: recv MSGF with 5199 bytes
debug: uasc 1/2: recv MSGF with 5199 bytes
debug: uasc 1/2: recv *ua.GetEndpointsResponse
debug: uasc 1/2: sending *ua.GetEndpointsResponse to handler
debug: uasc 1: Close()
debug: uasc 1/3: send *ua.CloseSecureChannelRequest with 57 bytes
debug: uasc 2/3: recv MSGF with 128 bytes
debug: uasc 2/3: recv *ua.ActivateSessionResponse
debug: uasc 2/3: sending *ua.ActivateSessionResponse to handler
debug: sub: pause
debug: client: monitor: start
debug: uasc 2/4: send *ua.ReadRequest with 128 bytes
debug: uacp 2: recv MSGF with 192 bytes
debug: uasc 2/4: recv MSGF with 192 bytes
debug: uasc 2/4: recv *ua.ReadResponse
debug: uasc 2/4: sending *ua.ReadResponse to handler
2022-02-18 16:24:43.758 info    D:/MyDocument/MyEclipseWorkspace/acuiot/backend/log/ginzap.go:25                                                                                                                                                                                                                                                                                /
api/opcua/connect{status 11 200  <nil>} {method 15 0 POST <nil>} {path 15 0 /api/opcua/connect <nil>} {query 15 0  <nil>} {ip 15 0 127.0.0.1 <nil>} {user-agent 15 0 PostmanRuntime/7.29.0 <nil>} {errors 15 0  <nil>} {cost 8 77629400  <nil>}
debug: uasc 2/5: send *ua.ReadRequest with 336 bytes
debug: uacp 2: recv MSGF with 160 bytes             
debug: uasc 2/5: recv MSGF with 160 bytes           
debug: uasc 2/5: recv *ua.ReadResponse              
debug: uasc 2/5: sending *ua.ReadResponse to handler
debug: uasc 2/6: send *ua.ReadRequest with 144 bytes
debug: uacp 2: recv MSGF with 96 bytes              
debug: uasc 2/6: recv MSGF with 96 bytes            
debug: uasc 2/6: recv *ua.ReadResponse              
debug: uasc 2/6: sending *ua.ReadResponse to handler
debug: uasc 2/7: send *ua.ReadRequest with 256 bytes
debug: uacp 2: recv MSGF with 112 bytes             
debug: uasc 2/7: recv MSGF with 112 bytes           
debug: uasc 2/7: recv *ua.ReadResponse              
debug: uasc 2/7: sending *ua.ReadResponse to handler
debug: uasc 2/8: send *ua.ReadRequest with 144 bytes
debug: uacp 2: recv MSGF with 96 bytes
debug: uasc 2/8: recv MSGF with 96 bytes
debug: uasc 2/8: recv *ua.ReadResponse
debug: uasc 2/8: sending *ua.ReadResponse to handler
2022-02-18 16:24:55.381 info    D:/MyDocument/MyEclipseWorkspace/acuiot/backend/log/ginzap.go:25                                                                                                                                                                                                                                                                                /
api/node/details{status 11 200  <nil>} {method 15 0 POST <nil>} {path 15 0 /api/node/details <nil>} {query 15 0  <nil>} {ip 15 0 127.0.0.1 <nil>} {user-agent 15 0 PostmanRuntime/7.29.0 <nil>} {errors 15 0  <nil>} {cost 8 10038500  <nil>}
debug: uasc 2/9: send *ua.ReadRequest with 336 bytes
debug: uacp 2: recv MSGF with 80 bytes
debug: uasc 2/9: recv MSGF with 80 bytes
debug: uasc 2/9: err: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: uasc 2/9: sending *ua.ServiceFault to handler
debug: client: monitor: disconnected
2022-02-18 16:26:51.884 info    D:/MyDocument/MyEclipseWorkspace/acuiot/backend/log/ginzap.go:25                                                                                                                                                                                                                                                                                /
api/node/details{status 11 500  <nil>} {method 15 0 POST <nil>} {path 15 0 /api/node/details <nil>} {query 15 0  <nil>} {ip 15 0 127.0.0.1 <nil>} {user-agent 15 0 PostmanRuntime/7.29.0 <nil>} {errors 15 0  <nil>} {cost 8 1500300  <nil>}
debug: client: monitor: auto-reconnecting
debug: client: monitor: action: createSecureChannel
debug: uacp 2: close
debug: sub: pause: pause
debug: uasc 2: readChunk EOF
debug: uasc 2: Close()
debug: client: monitor: trying to recreate secure channel
debug: uacp: connecting to opc.tcp://127.0.0.1:49320
debug: uacp 3: start HEL/ACK handshake
debug: uacp 3: sent HELF with 57 bytes
debug: uacp 3: recv ACKF with 28 bytes
debug: uacp 3: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x1000000, MaxChunkCount:0x1388}
debug: uasc 3/1: send *ua.OpenSecureChannelRequest with 1468 bytes
debug: uacp 3: recv OPNF with 1823 bytes
debug: uasc 3: setting securityPolicy to http://opcfoundation.org/UA/SecurityPolicy#Basic256
debug: uasc 3/1: recv OPNF with 1823 bytes
debug: uasc 3/1: recv *ua.OpenSecureChannelResponse
debug: uasc 3/1: sending *ua.OpenSecureChannelResponse to handler
debug: uasc 3: received security token. channelID=3085808354 tokenID=1 createdAt=2022-02-18T08:26:51Z lifetime=1h0m0s
debug: client: monitor: secure channel recreated
debug: client: monitor: action: restoreSession
debug: client: monitor: trying to restore session
debug: uasc 3: security token is refreshed at 2022-02-18T09:11:51Z (45m0s). channelID=3085808354 tokenID=1
debug: uasc 3: security token expires at 2022-02-18T09:41:51Z. channelID=3085808354 tokenID=1
debug: uasc 3/2: send *ua.ActivateSessionRequest with 752 bytes
debug: uacp 3: recv MSGF with 80 bytes
debug: uasc 3/2: recv MSGF with 80 bytes
debug: uasc 3/2: err: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: uasc 3/2: sending *ua.ServiceFault to handler
debug: client: monitor: restore session failed: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: client: monitor: action: recreateSession
debug: client: monitor: trying to recreate session
debug: uasc 3/3: send *ua.CreateSessionRequest with 1168 bytes
debug: uacp 3: recv MSGF with 6832 bytes
debug: uasc 3/3: recv MSGF with 6832 bytes
debug: uasc 3/3: recv *ua.CreateSessionResponse
debug: uasc 3/3: sending *ua.CreateSessionResponse to handler
debug: uasc 3/4: send *ua.ActivateSessionRequest with 752 bytes
debug: uacp 3: recv MSGF with 128 bytes
debug: uasc 3/4: recv MSGF with 128 bytes
debug: uasc 3/4: recv *ua.ActivateSessionResponse
debug: uasc 3/4: sending *ua.ActivateSessionResponse to handler
debug: uasc 3/5: send *ua.CloseSessionRequest with 96 bytes
debug: uacp 3: recv MSGF with 80 bytes
debug: uasc 3/5: recv MSGF with 80 bytes
debug: uasc 3/5: err: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: uasc 3/5: sending *ua.ServiceFault to handler
debug: client: monitor: session recreated
debug: client: monitor: trying to update namespaces
debug: uasc 3/6: send *ua.ReadRequest with 128 bytes
debug: uacp 3: recv MSGF with 192 bytes
debug: uasc 3/6: recv MSGF with 192 bytes
debug: uasc 3/6: recv *ua.ReadResponse
debug: uasc 3/6: sending *ua.ReadResponse to handler
debug: client: monitor: namespaces updated
debug: client: monitor: action: transferSubscriptions
debug: uasc 3/7: send *ua.TransferSubscriptionsRequest with 96 bytes
debug: uacp 3: recv MSGF with 80 bytes
debug: uasc 3/7: recv MSGF with 80 bytes
debug: uasc 3/7: err: There was nothing to do because the client passed a list of operations with no elements. StatusBadNothingToDo (0x800F0000)
debug: uasc 3/7: sending *ua.ServiceFault to handler
debug: client: monitor: transfer subscriptions failed. Recreating all subscriptions: There was nothing to do because the client passed a list of operations with no elements. StatusBadNothingToDo (0x800F0000)
debug: client: monitor: action: restoreSubscriptions
debug: client: monitor: resuming subscriptions
debug: client: monitor: resumed subscriptions
debug: sub: pause: resume
debug: publish: pendingAcks=[]
debug: publish: PublishRequest: {"RequestHeader":null,"SubscriptionAcknowledgements":[]}
debug: uasc 3/8: send *ua.PublishRequest with 96 bytes
debug: uacp 3: recv MSGF with 80 bytes
debug: uasc 3/8: recv MSGF with 80 bytes
debug: uasc 3/8: err: There is no subscription available for this session. StatusBadNoSubscription (0x80790000)
debug: uasc 3/8: sending *ua.ServiceFault to handler
debug: client: monitor: disconnected
debug: client: monitor: auto-reconnecting
debug: client: monitor: action: createSecureChannel
debug: uacp 3: close
debug: publish: PublishResponse: null
debug: uasc 3: readChunk EOF
debug: uasc 3: Close()
debug: client: monitor: trying to recreate secure channel
debug: uacp: connecting to opc.tcp://127.0.0.1:49320
debug: publish: error: no subscriptions but the publishing loop is still running: There is no subscription available for this session. StatusBadNoSubscription (0x80790000)
debug: sub: error: There is no subscription available for this session. StatusBadNoSubscription (0x80790000)
debug: sub: pause
debug: sub: pause: pause
debug: uacp 4: start HEL/ACK handshake
debug: uacp 4: sent HELF with 57 bytes
debug: uacp 4: recv ACKF with 28 bytes
debug: uacp 4: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x1000000, MaxChunkCount:0x1388}
debug: uasc 4/1: send *ua.OpenSecureChannelRequest with 1468 bytes
debug: uacp 4: recv OPNF with 1823 bytes
debug: uasc 4: setting securityPolicy to http://opcfoundation.org/UA/SecurityPolicy#Basic256
debug: uasc 4/1: recv OPNF with 1823 bytes
debug: uasc 4/1: recv *ua.OpenSecureChannelResponse
debug: uasc 4/1: sending *ua.OpenSecureChannelResponse to handler
debug: uasc 4: received security token. channelID=4233765659 tokenID=1 createdAt=2022-02-18T08:26:51Z lifetime=1h0m0s
debug: client: monitor: secure channel recreated
debug: client: monitor: action: restoreSession
debug: client: monitor: trying to restore session
debug: uasc 4: security token expires at 2022-02-18T09:41:51Z. channelID=4233765659 tokenID=1
debug: uasc 4: security token is refreshed at 2022-02-18T09:11:52Z (45m0s). channelID=4233765659 tokenID=1
debug: uasc 4/2: send *ua.ActivateSessionRequest with 752 bytes
debug: uacp 4: recv MSGF with 128 bytes
debug: uasc 4/2: recv MSGF with 128 bytes
debug: uasc 4/2: recv *ua.ActivateSessionResponse
debug: uasc 4/2: sending *ua.ActivateSessionResponse to handler
debug: uasc 4/3: send *ua.CloseSessionRequest with 96 bytes
debug: uacp 4: recv MSGF with 80 bytes
debug: uasc 4/3: recv MSGF with 80 bytes
debug: uasc 4/3: recv *ua.CloseSessionResponse
debug: uasc 4/3: sending *ua.CloseSessionResponse to handler
debug: client: monitor: session restored
debug: client: monitor: trying to update namespaces
debug: uasc 4/4: send *ua.ReadRequest with 128 bytes
debug: uacp 4: recv MSGF with 80 bytes
debug: uasc 4/4: recv MSGF with 80 bytes
debug: uasc 4/4: err: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: uasc 4/4: sending *ua.ServiceFault to handler
debug: client: monitor: updating namespaces failed: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: client: monitor: action: createSecureChannel
debug: uacp 4: close
debug: uasc 4: readChunk EOF
debug: uasc 4: Close()

flykarry avatar Feb 18 '22 08:02 flykarry

Which server?

magiconair avatar Feb 18 '22 09:02 magiconair

Which server?

KEPServerEX V6.5.829..0

flykarry avatar Feb 18 '22 09:02 flykarry

by the way , Does this client need a special server?

flykarry avatar Feb 24 '22 01:02 flykarry

No, it doesn't. We use it with a variety of servers and so do others.

magiconair avatar Mar 05 '22 06:03 magiconair

Hmm, it fails to restore the old session but then doesn't create a new one. I'll have a look.

magiconair avatar Mar 05 '22 06:03 magiconair

Hi @magiconair , Is this problem solved?

flykarry avatar Apr 08 '22 05:04 flykarry