Error reading OPC UA tags

Ignition
1

Hi, I am having a issue with reading OPC UA tags, usually during the server stop and start while importing the tags, I have used Kepware as OPC UA server which reads the tags from GE RX3i, I have created a number of data types in ignition and have almost around 7000 tags configured based on those types. I have also attached a copy of error log that I am getting.
io.netty.handler.codec.DecoderException: UaException: status=Bad_TcpMessageTooLarge, message=max chunk size exceeded (65535)

at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:418)

at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245)

at io.netty.handler.codec.ByteToMessageCodec.channelRead(ByteToMessageCodec.java:103)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)

at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962)

at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)

at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)

at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)

at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)

at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)

at java.lang.Thread.run(Unknown Source)

Caused by: org.eclipse.milo.opcua.stack.core.UaException: max chunk size exceeded (65535)

at org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler.accumulateChunk(UaTcpClientMessageHandler.java:429)

at org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler.onSecureMessage(UaTcpClientMessageHandler.java:615)

at org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler.decodeMessage(UaTcpClientMessageHandler.java:407)

at org.eclipse.milo.opcua.stack.client.handlers.UaTcpClientMessageHandler.decode(UaTcpClientMessageHandler.java:392)

at io.netty.handler.codec.ByteToMessageCodec$1.decode(ByteToMessageCodec.java:42)

at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387)

… 12 common frames omitted

2

This looks like a bug in Kepware.

What version of Ignition and what version of Kepware you using?

3

I am using kepware server EX 6.2 and Ignition 7.9.9, When I lunch quick client in ignition than I the status of all tags looks good, but it is not coming though in designer.

4

It might be worth upgrading to Kepware 6.6 to see if it stops happening.

Otherwise, if you could run Wireshark and be capturing while that log message occurs in Ignition I might be able to tell whether it’s a bug in Kepware or Ignition.

5 
Frame 129: 374 bytes on wire (2992 bits), 189 bytes captured (1512 bits) on interface 0
    Interface id: 0 (\Device\NPF_{A5F21CFF-BB90-4BFA-92A1-19E0171CE0AA})
        Interface name: \Device\NPF_{A5F21CFF-BB90-4BFA-92A1-19E0171CE0AA}
    Encapsulation type: NULL/Loopback (15)
    Arrival Time: Dec 12, 2018 12:40:14.669185000 W. Australia Standard Time
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1544589614.669185000 seconds
    [Time delta from previous captured frame: 0.000011000 seconds]
    [Time delta from previous displayed frame: 0.000000000 seconds]
    [Time since reference or first frame: 0.947896000 seconds]
    Frame Number: 129
    Frame Length: 374 bytes (2992 bits)
    Capture Length: 189 bytes (1512 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: null:ip:tcp:opcua]
    [Coloring Rule Name: TCP]
    [Coloring Rule String: tcp]
Null/Loopback
    Family: IP (2)
Internet Protocol Version 4, Src: localhost (127.0.0.1), Dst: localhost (127.0.0.1)
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 185
    Identification: 0x66b3 (26291)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 128
    Protocol: TCP (6)
    Header checksum: 0x0000 [validation disabled]
    [Header checksum status: Unverified]
    Source: localhost (127.0.0.1)
    Destination: localhost (127.0.0.1)
    [Source GeoIP: Unknown]
    [Destination GeoIP: Unknown]
Transmission Control Protocol, Src Port: 49320 (49320), Dst Port: 51284 (51284), Seq: 256, Ack: 1, Len: 145
    Source Port: 49320 (49320)
    Destination Port: 51284 (51284)
    [Stream index: 6]
    [TCP Segment Len: 145]
    Sequence number: 256    (relative sequence number)
    [Next sequence number: 401    (relative sequence number)]
    Acknowledgment number: 1    (relative ack number)
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·······AP···]
    Window size value: 29
    [Calculated window size: 29]
    [Window size scaling factor: -1 (unknown)]
    Checksum: 0xa499 [unverified]
    [Checksum Status: Unverified]
    Urgent pointer: 0
    [SEQ/ACK analysis]
        [Bytes in flight: 145]
        [Bytes sent since last PSH flag: 145]
    TCP payload (145 bytes)
    [PDU Size: 400]
    TCP segment data (145 bytes)
[2 Reassembled TCP Segments (400 bytes): #127(255), #129(145)]
    [Frame: 127, payload: 0-254 (255 bytes)]
    [Frame: 129, payload: 255-399 (145 bytes)]
    [Segment count: 2]
    [Reassembled TCP length: 400]
    [Reassembled TCP Data: 4d5347469001000045836c66010000006d0200006c000000...]
OpcUa Binary Protocol
    Message Type: MSG
    Chunk Type: F
    Message Size: 400
    SecureChannelId: 1718387525
    Security Token Id: 1
    Security Sequence Number: 621
    Security RequestId: 108
    OpcUa Service : Encodeable Object
        TypeId : ExpandedNodeId
            NodeId EncodingMask: Four byte encoded Numeric (0x01)
            NodeId Namespace Index: 0
            NodeId Identifier Numeric: PublishResponse (829)
        PublishResponse
            ResponseHeader: ResponseHeader
                Timestamp: Dec 12, 2018 12:40:14.667309600 W. Australia Standard Time
                RequestHandle: 106
                ServiceResult: 0x00000000 [Good]
                ServiceDiagnostics: DiagnosticInfo
                    EncodingMask: 0x00
                        .... ...0 = has symbolic id: False
                        .... ..0. = has namespace: False
                        .... .0.. = has localizedtext: False
                        .... 0... = has locale: False
                        ...0 .... = has additional info: False
                        ..0. .... = has inner statuscode: False
                        .0.. .... = has inner diagnostic info: False
                StringTable: Array of String
                    ArraySize: 0
                AdditionalHeader: ExtensionObject
                    TypeId: ExpandedNodeId
                        EncodingMask: 0x00, EncodingMask: Two byte encoded Numeric
                            .... 0000 = EncodingMask: Two byte encoded Numeric (0x0)
                            .0.. .... = has server index: False
                            0... .... = has namespace uri: False
                        Identifier Numeric: 0
                    EncodingMask: 0x00
                        .... ...0 = has binary body: False
                        .... ..0. = has xml body: False
            SubscriptionId: 1
            AvailableSequenceNumbers: Array of UInt32
                ArraySize: 1
                [0]: AvailableSequenceNumbers: 57
            MoreNotifications: False
            NotificationMessage: NotificationMessage
                SequenceNumber: 57
                PublishTime: Dec 12, 2018 12:40:14.667309600 W. Australia Standard Time
                NotificationData: Array of ExtensionObject
                    ArraySize: 1
                    [0]: ExtensionObject
                        TypeId: ExpandedNodeId
                            EncodingMask: 0x01, EncodingMask: Four byte encoded Numeric
                                .... 0001 = EncodingMask: Four byte encoded Numeric (0x1)
                                .0.. .... = has server index: False
                                0... .... = has namespace uri: False
                            Namespace Index: 0
                            Identifier Numeric: 811
                        EncodingMask: 0x01, has binary body
                            .... ...1 = has binary body: True
                            .... ..0. = has xml body: False
                        DataChangeNotification: DataChangeNotification
                            MonitoredItems: Array of MonitoredItemNotification
                                ArraySize: 9
                                [0]: MonitoredItemNotification
                                    ClientHandle: 828
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 1.09615855150477
                                        SourceTimestamp: Dec 12, 2018 12:40:14.651308000 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:14.651308000 W. Australia Standard Time
                                [1]: MonitoredItemNotification
                                    ClientHandle: 2765
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 9.49547345241008
                                        SourceTimestamp: Dec 12, 2018 12:40:14.660308900 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:14.660308900 W. Australia Standard Time
                                [2]: MonitoredItemNotification
                                    ClientHandle: 6648
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 0.0117445559089797
                                        SourceTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                [3]: MonitoredItemNotification
                                    ClientHandle: 6816
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 158.306826523122
                                        SourceTimestamp: Dec 12, 2018 12:40:13.722215100 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:13.722215100 W. Australia Standard Time
                                [4]: MonitoredItemNotification
                                    ClientHandle: 1322
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 0.101786151211157
                                        SourceTimestamp: Dec 12, 2018 12:40:14.650307900 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:14.650307900 W. Australia Standard Time
                                [5]: MonitoredItemNotification
                                    ClientHandle: 3671
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 81.7714705162711
                                        SourceTimestamp: Dec 12, 2018 12:40:14.660308900 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:14.660308900 W. Australia Standard Time
                                [6]: MonitoredItemNotification
                                    ClientHandle: 4270
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 17.8615121115733
                                        SourceTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                [7]: MonitoredItemNotification
                                    ClientHandle: 5328
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 380.474675801321
                                        SourceTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:13.683211200 W. Australia Standard Time
                                [8]: MonitoredItemNotification
                                    ClientHandle: 6964
                                    Value: DataValue
                                        EncodingMask: 0x0d, has value, has source timestamp, has server timestamp
                                            .... ...1 = has value: True
                                            .... ..0. = has statuscode: False
                                            .... .1.. = has source timestamp: True
                                            .... 1... = has server timestamp: True
                                            ...0 .... = has source picoseconds: False
                                            ..0. .... = has server picoseconds: False
                                        Value: Variant
                                            Variant Type: Double (0x0b)
                                            Double: 10.3009542451676
                                        SourceTimestamp: Dec 12, 2018 12:40:13.693212200 W. Australia Standard Time
                                        ServerTimestamp: Dec 12, 2018 12:40:13.693212200 W. Australia Standard Time
                            DiagnosticInfos: Array of DiagnosticInfo
                                ArraySize: 0
            Results: Array of StatusCode
                ArraySize: 1
                [0]: Results: 0x00000000 [Good]
            DiagnosticInfos: Array of DiagnosticInfo
                ArraySize: 0
6

It seems to be working back again, the only thing that I did was deleted and recreated the endpoint and removed the encryption in order to capture the logs in wireshark, I usually come across these errors when I try to add couple of new tags so, have to start and stop the server while importing tags, and usually issue get resolved when I go to the each of the data types and click apply so it assumes to be like refreshing, Kepserver seems to be working fine as its shows the client connection and all the active tags, and also when I try to run the client on ignition it reads and writes on all the tag,

7

Turning encryption off is probably what made it work again. Normally you do need to do this for a capture, but in this case you can leave it on because I only need to see the size of the message chunks Kepware sends and that information will not be encrypted.

8

TurnedFrame 24000: 86 bytes on wire (688 bits), 45 bytes captured (360 bits) on interface 0
Interface id: 0 (\Device\NPF_{A5F21CFF-BB90-4BFA-92A1-19E0171CE0AA})
Encapsulation type: NULL/Loopback (15)
Arrival Time: Dec 13, 2018 08:18:18.475206000 W. Australia Standard Time
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1544660298.475206000 seconds
[Time delta from previous captured frame: 0.000005000 seconds]
[Time delta from previous displayed frame: 0.007295000 seconds]
[Time since reference or first frame: 228.315396000 seconds]
Frame Number: 24000
Frame Length: 86 bytes (688 bits)
Capture Length: 45 bytes (360 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: null:ip:tcp:opcua]
[Coloring Rule Name: TCP]
[Coloring Rule String: tcp]
Null/Loopback
Internet Protocol Version 4, Src: localhost (127.0.0.1), Dst: localhost (127.0.0.1)
Transmission Control Protocol, Src Port: 49320 (49320), Dst Port: 54841 (54841), Seq: 70180, Ack: 799417, Len: 1
[258 Reassembled TCP Segments (65536 bytes): #23486(255), #23488(255), #23490(255), #23492(255), #23494(255), #23496(255), #23498(255), #23500(255), #23502(255), #23504(255), #23506(255), #23508(255), #23510(255), #23512(255), #23514(255), ]
OpcUa Binary Protocol
Message Type: MSG
Chunk Type: C
Message Size: 65536
SecureChannelId: 2942927863
Security Token Id: 1
Security Sequence Number: 1766523542
Security RequestId: 1668928874
encryption back on again, came across the same issue,

9

Can you give me an actual capture? Email it to me (kevin@ ) or support.

edit:

This looks damning though:

OpcUa Binary Protocol
Message Type: MSG
Chunk Type: C
Message Size: 65536       <--------- 65536 is greater than 65535
SecureChannelId: 2942927863
Security Token Id: 1
Security Sequence Number: 1766523542
Security RequestId: 1668928874
10

@sagar.kc I think you’ll need to contact Kepware support on this one. It seems pretty clear that they are occasionally miscalculating the chunk size and sending a chunk that is larger than the negotiated max.

There’s 4 instances of it happening in the capture you emailed me (10606, 24000, 36885, 49553). All off by one.

As I mentioned earlier, you might save yourself some trouble by upgrading Kepware to 6.6 before you get their support involved in case that fixes it.

11

Thank you Kevin, I will upgrade it first and see how it goes.

12

Please keep me updated as this progresses. I remember our support department seeing this issue with another one of our customers but they opted to just turn security off and never got Wireshark captures so I wasn’t able to confirm the bug was on Kepware’s side as we’ve done here.

1 Like
13

will do Kevin, Thanks for your support.

14

Just update Kepserver to 6.6.348.0, it seems to be working with the encryption on as well, I will update you, if I came across same issues back again, hope I will not. Thank you for your support Kevin.