BadSequenceNumberInvalid

[lov3b]

Hey, and sorry for bothering you once again.
We're having troubles with the server/client again. It spits out the error BadSequenceNumberInvalid in a reproducible manner. It almost always complains for the following:

[2025-07-15 09:46:45] ERROR: BadSequenceNumberInvalid: Chunk sequence number of 32 is not the expected value of 12, idx 0

We get around 8 such messages and one message with a lower sequence number such as:

[2025-07-15 09:49:03] ERROR: BadSequenceNumberInvalid: Chunk sequence number of 27 is not the expected value of 12, idx 0

Below follows a log around the error

[2025-07-15 11:01:35] TRACE: data change notification = DataChangeNotification { monitored_items: Some([MonitoredItemNotification { client_handle: 1565, value: DataValue { value: Some(Int16(490)), status: None, source_timestamp: Some(DateTime { date_time: 2025-07-15T09:01:35.053438900Z }), source_picoseconds: None, server_timestamp: None, server_picoseconds: None } }]), diagnostic_infos: None }
[2025-07-15 11:01:35] TRACE: Sending notification message NotificationMessage { sequence_number: 464, publish_time: DateTime { date_time: 2025-07-15T09:01:35.193977Z }, notification_data: Some([ExtensionObject { body: Some(DataChangeNotification { monitored_items: Some([MonitoredItemNotification { client_handle: 1565, value: DataValue { value: Some(Int16(490)), status: None, source_timestamp: Some(DateTime { date_time: 2025-07-15T09:01:35.053438900Z }), source_picoseconds: None, server_timestamp: None, server_picoseconds: None } }]), diagnostic_infos: None }) }]) }
[2025-07-15 11:01:35] TRACE: Decrementing life time counter 17
[2025-07-15 11:01:35] TRACE: Writing request to buffer
[2025-07-15 11:01:35] TRACE: Creating a chunk with a size of 122, data excluding padding & signature
[2025-07-15 11:01:35] TRACE: Received chunk with sequence number 8452
[2025-07-15 11:01:35] DEBUG: Incoming request; request_id=8450 request_type=Publish request_handle=1013447
[2025-07-15 11:01:35] TRACE: -> Incoming request;
[2025-07-15 11:01:35] DEBUG: Received request on session 2
[2025-07-15 11:01:35] TRACE: <- Incoming request;
[2025-07-15 11:01:35] TRACE: -- Incoming request;
[2025-07-15 11:01:35] DEBUG: Message 1020 timed out
[2025-07-15 11:01:35] DEBUG: session:1 Publish request timed out
[2025-07-15 11:01:35] TRACE: Writing request to buffer
[2025-07-15 11:01:35] TRACE: Creating a chunk with a size of 52, data excluding padding & signature
[2025-07-15 11:01:35] DEBUG: Sending publish due to internal tick
[2025-07-15 11:01:35] TRACE: Writing request to buffer
[2025-07-15 11:01:35] TRACE: Creating a chunk with a size of 98, data excluding padding & signature
[2025-07-15 11:01:35] TRACE: Received chunk with sequence number 147
[2025-07-15 11:01:35] DEBUG: Incoming request; request_id=1147 request_type=Publish request_handle=9154
[2025-07-15 11:01:35] TRACE: -> Incoming request;
[2025-07-15 11:01:35] DEBUG: Received request on session 1
[2025-07-15 11:01:35] TRACE: <- Incoming request;
[2025-07-15 11:01:35] TRACE: -- Incoming request;
[2025-07-15 11:01:35] TRACE: Decrementing life time counter 27366
*Truncated Decrementing life time counter*
[2025-07-15 11:01:35] TRACE: Decrementing life time counter 27369
[2025-07-15 11:01:35] TRACE: Decrementing life time counter 118
[2025-07-15 11:01:35] TRACE: Decrementing life time counter 16
[2025-07-15 11:01:35] DEBUG: Message 1021 timed out
[2025-07-15 11:01:35] DEBUG: session:1 Publish request timed out
[2025-07-15 11:01:35] TRACE: Writing request to buffer
[2025-07-15 11:01:35] TRACE: Creating a chunk with a size of 52, data excluding padding & signature
[2025-07-15 11:01:36] DEBUG: Sending publish due to internal tick
[2025-07-15 11:01:36] TRACE: Writing request to buffer
[2025-07-15 11:01:36] TRACE: Creating a chunk with a size of 98, data excluding padding & signature
[2025-07-15 11:01:36] TRACE: Received chunk with sequence number 148
[2025-07-15 11:01:36] DEBUG: Incoming request; request_id=1148 request_type=Publish request_handle=9155
[2025-07-15 11:01:36] TRACE: -> Incoming request;
[2025-07-15 11:01:36] DEBUG: Received request on session 1
[2025-07-15 11:01:36] TRACE: <- Incoming request;
[2025-07-15 11:01:36] TRACE: -- Incoming request;
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27365
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27367
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27368
*Truncated Decrementing life time counter*
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27368
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 117
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 15
[2025-07-15 11:01:36] DEBUG: Message 1022 timed out
[2025-07-15 11:01:36] DEBUG: session:1 Publish request timed out
[2025-07-15 11:01:36] TRACE: Writing request to buffer
[2025-07-15 11:01:36] TRACE: Creating a chunk with a size of 52, data excluding padding & signature
[2025-07-15 11:01:36] DEBUG: Sending publish due to internal tick
[2025-07-15 11:01:36] TRACE: Writing request to buffer
[2025-07-15 11:01:36] TRACE: Creating a chunk with a size of 98, data excluding padding & signature
[2025-07-15 11:01:36] TRACE: Received chunk with sequence number 149
[2025-07-15 11:01:36] DEBUG: Incoming request; request_id=1149 request_type=Publish request_handle=9156
[2025-07-15 11:01:36] TRACE: -> Incoming request;
[2025-07-15 11:01:36] DEBUG: Received request on session 1
[2025-07-15 11:01:36] TRACE: <- Incoming request;
[2025-07-15 11:01:36] TRACE: -- Incoming request;
[2025-07-15 11:01:36] DEBUG: Message 1023 timed out
[2025-07-15 11:01:36] DEBUG: session:1 Publish request timed out
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27364
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27366
*Truncated Decrementing life time counter*
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 27367
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 116
[2025-07-15 11:01:36] TRACE: Decrementing life time counter 14
[2025-07-15 11:01:36] TRACE: Writing request to buffer
[2025-07-15 11:01:36] TRACE: Creating a chunk with a size of 52, data excluding padding & signature
[2025-07-15 11:01:37] DEBUG: Sending publish due to internal tick
[2025-07-15 11:01:37] TRACE: Writing request to buffer
[2025-07-15 11:01:37] TRACE: Creating a chunk with a size of 98, data excluding padding & signature
[2025-07-15 11:01:37] TRACE: Received chunk with sequence number 150
[2025-07-15 11:01:37] DEBUG: Incoming request; request_id=1150 request_type=Publish request_handle=9157
[2025-07-15 11:01:37] TRACE: -> Incoming request;
[2025-07-15 11:01:37] DEBUG: Received request on session 1
[2025-07-15 11:01:37] TRACE: <- Incoming request;
[2025-07-15 11:01:37] TRACE: -- Incoming request;
[2025-07-15 11:01:37] DEBUG: Message 1024 timed out
[2025-07-15 11:01:37] DEBUG: session:1 Publish request timed out
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 27363
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 27365
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 27366
*Truncated Decrementing life time counter*
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 27366
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 115
[2025-07-15 11:01:37] TRACE: Decrementing life time counter 13
[2025-07-15 11:01:37] TRACE: Writing request to buffer
[2025-07-15 11:01:37] TRACE: Creating a chunk with a size of 52, data excluding padding & signature
[2025-07-15 11:01:37] DEBUG: Sending publish due to internal tick
[2025-07-15 11:01:37] TRACE: Writing request to buffer
[2025-07-15 11:01:37] TRACE: Creating a chunk with a size of 98, data excluding padding & signature
[2025-07-15 11:01:37] TRACE: Received chunk with sequence number 151
[2025-07-15 11:01:37] DEBUG: Incoming request; request_id=1151 request_type=Publish request_handle=9158
[2025-07-15 11:01:37] TRACE: -> Incoming request;
[2025-07-15 11:01:37] DEBUG: Received request on session 1
[2025-07-15 11:01:37] TRACE: <- Incoming request;
[2025-07-15 11:01:37] TRACE: -- Incoming request;
[2025-07-15 11:01:37] TRACE: Writing request to buffer
[2025-07-15 11:01:37] TRACE: Creating a chunk with a size of 128, data excluding padding & signature
[2025-07-15 11:01:37] TRACE: Received chunk with sequence number 152
[2025-07-15 11:01:37] DEBUG: Incoming request; request_id=1152 request_type=Read request_handle=9159
[2025-07-15 11:01:37] TRACE: -> Incoming request;
[2025-07-15 11:01:37] DEBUG: Received request on session 1
[2025-07-15 11:01:37] TRACE: <- Incoming request;
[2025-07-15 11:01:37] TRACE: -- Incoming request;
[2025-07-15 11:01:37] TRACE: -> Incoming request;
[2025-07-15 11:01:37] TRACE: <- Incoming request;
[2025-07-15 11:01:37] DEBUG: Read; node_manager=core
[2025-07-15 11:01:37] TRACE: -> Read;
[2025-07-15 11:01:37] TRACE: <- Read;
[2025-07-15 11:01:37] TRACE: -> Read;
[2025-07-15 11:01:37] TRACE: <- Read;
[2025-07-15 11:01:37] TRACE: -- Read;
[2025-07-15 11:01:37] TRACE: -> Incoming request;
[2025-07-15 11:01:37] DEBUG: Sending response of type Read status_code=Good
[2025-07-15 11:01:37] TRACE: <- Incoming request;
[2025-07-15 11:01:37] TRACE: -- Incoming request;
[2025-07-15 11:01:37] TRACE: Writing request to buffer
[2025-07-15 11:01:37] TRACE: Creating a chunk with a size of 86, data excluding padding & signature
[2025-07-15 11:01:37] TRACE: receive chunk final 1152:32. Length 62
[2025-07-15 11:01:37] TRACE: Received chunk with sequence number 32
[2025-07-15 11:01:37] TRACE: Expected sequence number 12, got 32
[2025-07-15 11:01:37] ERROR: BadSequenceNumberInvalid: Chunk sequence number of 32 is not the expected value of 12, idx 0
[2025-07-15 11:01:37] WARN: session:1 Transport disconnected: BadSequenceNumberInvalid

Once again, thank you for your time and patience! We're not sure what causes it, but a possible explanation could be that it arises when a subscription is about to be triggered in the embedded client that we've connected to the server. Any ideas?

[einarmo]

It's a bit tricky to say for sure what this is, this error comes from the core of the protocol itself, the part that decodes messages from the other party, but it's really hard to say for sure. Are you talking to a third party server with this? There's a lot going on in these logs...

I see it comes with a timed out publish request, maybe that's relevant? I'd still like some more information, as based on just this it's hard to reproduce.

[lov3b]

Sorry, I'll not be working in the project that made use of this for quite some time now. Therefore, I unfortunately don't have any more data for you. One thing that I remember is that a product in the system would periodically ping the server, to see if it was still up. Is it possible that it was the culprit?

[Tarcontar]

Hi, I am getting the same error: BadSequenceNumberInvalid: Chunk sequence number of 28 is not the expected value of 25, idx 0.

Initially everything is fine, but after some time this pops up:

Might have to do with created subscriptions.

Cheers