Potential Bug: StatusBadTimeout Error when attempting connection using numeric id #478

jnangle · 2021-10-07T14:38:35Z

Team,

I'm experiencing an error when I attempt to connect to an OPC UA server (Red Lion, Crimson 3.1) when using numeric tag ids. The error shows up when running the regread example. I am including output here from read, regread, and monitor examples to illustrate where the error occurs:

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/read/read.go -endpoint opc.tcp://10.79.116.248:4840 -node "ns=2;i=1764"
19.443002700805664

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/regread/regread.go -endpoint opc.tcp://10.79.116.248:4840 -node "ns=2;i=1764"
RegisterNodes failed: The operation timed out. StatusBadTimeout (0x800A0000)
exit status 1

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/monitor/monitor.go -endpoint opc.tcp://10.79.116.248:4840 -node "ns=2;i=1764"
2021/10/07 08:17:31 *http://opcfoundation.org/UA/SecurityPolicy#NoneMessageSecurityModeNone
2021/10/07 08:17:31 [channel ] sub=2435 ts=2021-10-07T14:15:38Z node=ns=2;i=1764 value=19.438425064086914
2021/10/07 08:17:31 [callback] sub=2436 ts=2021-10-07T14:15:38Z node=ns=2;i=1764 value=19.438425064086914
2021/10/07 08:17:32 [channel ] sub=2435 ts=2021-10-07T14:15:39Z node=ns=2;i=1764 value=19.42011260986328
2021/10/07 08:17:32 [callback] sub=2436 ts=2021-10-07T14:15:39Z node=ns=2;i=1764 value=19.42011260986328
2021/10/07 08:17:33 [channel ] sub=2435 ts=2021-10-07T14:15:40Z node=ns=2;i=1764 value=19.447580337524414
2021/10/07 08:17:33 [callback] sub=2436 ts=2021-10-07T14:15:40Z node=ns=2;i=1764 value=19.447580337524414
^C
2021/10/07 08:17:33 stats: sub=2436 delivered=3 dropped=0
2021/10/07 08:17:33 stats: sub=2435 delivered=3 dropped=0
jnangle-31556s:opcua@v0.1.13 jnangle$

However regread seems to work find when connecting to a Kepware server using string ids.

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/read/read.go -endpoint opc.tcp://10.79.116.250:49320 -node "ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity"
19.465892791748047

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/regread/regread.go -endpoint opc.tcp://10.79.116.250:49320 -node "ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity"
19.447580337524414

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/monitor/monitor.go -endpoint opc.tcp://10.79.116.250:49320 -node "ns=2;UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity"
2021/10/07 08:15:29 *http://opcfoundation.org/UA/SecurityPolicy#NoneMessageSecurityModeNone
2021/10/07 08:15:30 [callback] sub=8 ts=2021-10-07T14:13:36Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.452159881591797
2021/10/07 08:15:30 [channel ] sub=7 ts=2021-10-07T14:13:36Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.452159881591797
2021/10/07 08:15:31 [channel ] sub=7 ts=2021-10-07T14:13:38Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.456737518310547
2021/10/07 08:15:31 [callback] sub=8 ts=2021-10-07T14:13:38Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.456737518310547
2021/10/07 08:15:32 [channel ] sub=7 ts=2021-10-07T14:13:39Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.42469024658203
2021/10/07 08:15:32 [callback] sub=8 ts=2021-10-07T14:13:39Z node=ns=2;s=UA Server.Red Lion DA50.V1.Stack.OPC_STB1_Hallway_DIWater_Resistivity value=19.42469024658203
^C
2021/10/07 08:15:33 stats: sub=7 delivered=3 dropped=0
2021/10/07 08:15:33 stats: sub=8 delivered=3 dropped=0
jnangle-31556s:opcua@v0.1.13

I have been using Telegraf to set up connections to OPC UA servers. Since Telegraf uses the gopcua library, I wanted to open a ticket here.

Thank you in advance for taking a look at this.

The text was updated successfully, but these errors were encountered:

jnangle · 2021-10-25T15:17:21Z

Bumping this issue to see if anyone is interested in looking at it.

kung-foo · 2021-10-25T20:16:46Z

Hi @jnangle since I don't have access to your type of OPC-UA server, you would need to provide either debug log output or even better, a wireshark capture (assuming an unencrypted connection).

jnangle · 2021-10-25T22:42:11Z

Hi @kung-foo,

Thanks for the message. I am including a debug output for both the regread example (which fails) and the read example (which works). Hopefully there is enough information to help you get started. If not, I can work on getting a wireshark capture.

jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/regread/regread.go -endpoint opc.tcp://10.79.116.248:4840 -node "ns=2;i=1030" -debug
debug: Connect to opc.tcp://10.79.116.248:4840
debug: conn 1: start HEL/ACK handshake
debug: conn 1: sent HELF with 60 bytes
debug: conn 1: recv ACKF with 28 bytes
debug: conn 1: server has no chunk limit. Using 512
debug: conn 1: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x1000000, MaxChunkCount:0x200}
debug: uasc 1/1: send *ua.OpenSecureChannelRequest with 132 bytes
debug: conn 1: recv OPNF with 135 bytes
debug: uasc OPN Request
debug: uasc 1/1: recv OPNF with 135 bytes
debug: uasc 1/1: recv *ua.OpenSecureChannelResponse
debug: sending *ua.OpenSecureChannelResponse to handler
debug: received security token: channelID=5 tokenID=1 createdAt=2021-10-25T21:51:36Z lifetime=1h0m0s
debug: uasc 1/2: send *ua.CreateSessionRequest with 267 bytes
debug: conn 1: recv MSGF with 547 bytes
debug: uasc 1/2: recv MSGF with 547 bytes
debug: uasc 1/2: recv *ua.CreateSessionResponse
debug: sending *ua.CreateSessionResponse to handler
debug: uasc 1/3: send *ua.ActivateSessionRequest with 114 bytes
debug: conn 1: recv MSGF with 64 bytes
debug: uasc 1/3: recv MSGF with 64 bytes
debug: uasc 1/3: recv *ua.ActivateSessionResponse
debug: sending *ua.ActivateSessionResponse to handler
debug: uasc 1/4: send *ua.RegisterNodesRequest with 67 bytes
debug: conn 1: recv ERRF with 16 bytes
debug: uasc readChunk EOF
RegisterNodes failed: The operation timed out. StatusBadTimeout (0x800A0000)
exit status 1
jnangle-31556s:opcua@v0.1.13 jnangle$ go run examples/read/read.go -endpoint opc.tcp://10.79.116.248:4840 -node "ns=2;i=1030" -debug
debug: Connect to opc.tcp://10.79.116.248:4840
debug: conn 1: start HEL/ACK handshake
debug: conn 1: sent HELF with 60 bytes
debug: conn 1: recv ACKF with 28 bytes
debug: conn 1: server has no chunk limit. Using 512
debug: conn 1: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x1000000, MaxChunkCount:0x200}
debug: uasc 1/1: send *ua.OpenSecureChannelRequest with 132 bytes
debug: conn 1: recv OPNF with 135 bytes
debug: uasc OPN Request
debug: uasc 1/1: recv OPNF with 135 bytes
debug: uasc 1/1: recv *ua.OpenSecureChannelResponse
debug: sending *ua.OpenSecureChannelResponse to handler
debug: received security token: channelID=6 tokenID=1 createdAt=2021-10-25T21:52:43Z lifetime=1h0m0s
debug: uasc 1/2: send *ua.CreateSessionRequest with 267 bytes
debug: conn 1: recv MSGF with 547 bytes
debug: uasc 1/2: recv MSGF with 547 bytes
debug: uasc 1/2: recv *ua.CreateSessionResponse
debug: sending *ua.CreateSessionResponse to handler
debug: uasc 1/3: send *ua.ActivateSessionRequest with 114 bytes
debug: conn 1: recv MSGF with 64 bytes
debug: uasc 1/3: recv MSGF with 64 bytes
debug: uasc 1/3: recv *ua.ActivateSessionResponse
debug: sending *ua.ActivateSessionResponse to handler
debug: uasc 1/4: send *ua.ReadRequest with 93 bytes
debug: conn 1: recv MSGF with 86 bytes
debug: uasc 1/4: recv MSGF with 86 bytes
debug: uasc 1/4: recv *ua.ReadResponse
debug: sending *ua.ReadResponse to handler
34.599998474121094
debug: uasc 1/5: send *ua.CloseSessionRequest with 60 bytes
debug: conn 1: recv MSGF with 52 bytes
debug: uasc 1/5: recv MSGF with 52 bytes
debug: uasc 1/5: recv *ua.CloseSessionResponse
debug: sending *ua.CloseSessionResponse to handler
debug: uasc Close()
debug: uasc 1/6: send *ua.CloseSecureChannelRequest with 57 bytes
debug: uasc readChunk EOF
debug: conn 1: close
jnangle-31556s:opcua@v0.1.13 jnangle$

magiconair · 2021-10-26T05:25:03Z

Looks like the server doesn't like the ua.RegisterNodesRequest we are sending. Wireshark would help but what would also help is a tcpdump of a successful call with ua.RegisterNodesRequest from another client if you have something like this. I'm assuming this works with a different client.

Error handling looks a bit off. I'm curious what is in the ERRF response from the server.

jnangle · 2021-11-23T21:22:10Z

Hello @magiconair ,

I am attaching a Wireshark capture of a successful connection to my Red Lion OPC UA server. The client is an Influx logger for OPCUA from a company called Factry.io. I'm able to successfully connect to the Red Lion and get data from a node using numeric ids.

I hope this is helpful to you. Please let me know if there is anything else I can do to help.

My apologies for taking so long to get this to you
opcua-redlion-success.pcapng.zip
.

magiconair · 2021-11-23T22:42:19Z

Hi @jnangle , no worries and thank you for the tcpdump. I'll have a quick look.

magiconair · 2021-11-23T22:43:09Z

@jnangle can you also capture the failed attempt from the gopcua library?

magiconair · 2021-11-23T22:47:56Z

Hmm, @jnangle this dump does not contain any registered reads or any reads. This is only using subscriptions. Can you try to perform a registered read with another client and confirm that this works?

jnangle · 2021-11-24T17:28:57Z

Hello again, @magiconair,

After I received your last message yesterday, I downloaded the gopcua library and ran the read and regread example code against a Kepware server and the Red Lion server. Using string ids with Kepware, both commands completed successfully.

Using numeric ids with the Red Lion server, the read command ran successfully, while the regread command failed. From line 82-83 in the Red Lion Wireshark trace, it looks like the Red Lion server returns a BadServiceUnsupported error to the RegisterNodesRequest. So, that may be the problem.

The file I am attaching includes screenshots from running both commands against the two servers so you can see the results. I am also including Wireshark traces for both servers so you can see the details.

I will be off until Monday for the Thanksgiving holiday, but I hope I have provided enough information for you in this attachment. I'm happy to provided additional information if needed.

OPCUA-RedLion-Diags.zip

magiconair · 2021-11-24T19:26:34Z

Maybe it doesn’t make sense to register numeric ids fir that server. It would be unhelpful since you have to parse and group ids before you register them but possible. — Frank Schröder

…

On 24. Nov 2021, at 18:29, John Nangle ***@***.***> wrote: Hello again, @magiconair, After I received your last message yesterday, I downloaded the gopcua library and ran the read and regread example code against a Kepware server and the Red Lion server. Using string ids with Kepware, both commands completed successfully. Using numeric ids with the Red Lion server, the read command ran successfully, while the regread command failed. From line 82-83 in the Red Lion Wireshark trace, it looks like the Red Lion server returns a BadServiceUnsupported error to the RegisterNodesRequest. So, that may be the problem. The file I am attaching includes screenshots from running both commands against the two servers so you can see the results. I am also including Wireshark traces for both servers so you can see the details. I will be off until Monday for the Thanksgiving holiday, but I hope I have provided enough information for you in this attachment. I'm happy to provided additional information if needed. OPCUA-RedLion-Diags.zip — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

jnangle · 2021-11-29T16:05:17Z

It's possible that they deploy a "minimum requirements" OPC UA server. I did call Red Lion support to ask about using string ids, and I was told, "No. You get what you get." So, I think we're stuck with numeric ids.

From the Telegraf perspective, it's necessary to create an entry in the Telegraf config file for each OPC UA tag. So I'm not sure how much tag registration adds to the capability. I'm not familiar with the OPC UA spec.

magiconair · 2022-02-15T05:26:18Z

Tag registration is an optimization for frequent reads of nodes. These could be nodes actually living on another OPC/UA server which the local server proxies or you get a numeric id back for a string id so that the server doesn't have to compute the hash every time. In any case, they are not required for normal operation.

In addition, we also just discovered that the auto-reconnect of gocpua v0.2 creates an issue with registered reads since the node ids are no longer valid after a reconnect. We handle subscriptions gracefully by re-registering the monitored items but not the registered reads. I'll create a ticket for this so that we can add support to the client if possible.

I am closing this ticket since this looks like registered reads are not supported in the RedLion server and for now it might be better to not use them unless you also handle the reconnect case.

magiconair · 2022-02-15T05:33:32Z

Created #557

jnangle changed the title ~~Potential Bug: StatusBadTimeout Error when attempting connection use numeric id~~ Potential Bug: StatusBadTimeout Error when attempting connection using numeric id Oct 7, 2021

jnangle mentioned this issue Oct 12, 2021

Read failed: opcua: invalid extension object with id ns=4;i=5086 influxdata/telegraf#9900

Closed

sjwang90 mentioned this issue Nov 4, 2021

OPC-UA input plugin roadmap influxdata/telegraf#10062

Open

12 tasks

mharjula mentioned this issue Dec 16, 2021

OPC UA Events based plugin influxdata/telegraf#8083

Closed

magiconair closed this as completed Feb 15, 2022

magiconair mentioned this issue Feb 15, 2022

Telegraf OPCUA runtime error: invalid memory address or nil pointer dereference influxdata/telegraf#9164

Closed

powersj mentioned this issue Aug 2, 2024

OPCUA plugin fails to connect to OPCUA server from Codesys when running on groov RIO influxdata/telegraf#15701

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Potential Bug: StatusBadTimeout Error when attempting connection using numeric id #478

Potential Bug: StatusBadTimeout Error when attempting connection using numeric id #478

jnangle commented Oct 7, 2021

jnangle commented Oct 25, 2021

kung-foo commented Oct 25, 2021

jnangle commented Oct 25, 2021

magiconair commented Oct 26, 2021

jnangle commented Nov 23, 2021

magiconair commented Nov 23, 2021

magiconair commented Nov 23, 2021

magiconair commented Nov 23, 2021

jnangle commented Nov 24, 2021

magiconair commented Nov 24, 2021 via email

jnangle commented Nov 29, 2021

magiconair commented Feb 15, 2022

magiconair commented Feb 15, 2022

Potential Bug: StatusBadTimeout Error when attempting connection using numeric id #478

Potential Bug: StatusBadTimeout Error when attempting connection using numeric id #478

Comments

jnangle commented Oct 7, 2021

jnangle commented Oct 25, 2021

kung-foo commented Oct 25, 2021

jnangle commented Oct 25, 2021

magiconair commented Oct 26, 2021

jnangle commented Nov 23, 2021

magiconair commented Nov 23, 2021

magiconair commented Nov 23, 2021

magiconair commented Nov 23, 2021

jnangle commented Nov 24, 2021

magiconair commented Nov 24, 2021 via email

jnangle commented Nov 29, 2021

magiconair commented Feb 15, 2022

magiconair commented Feb 15, 2022