Closed
Description
Observed behavior
Submitting it as a defect, however, feel free to move it into discussions if I misunderstood how Nats is supposed to work.
I am running a standalone node with Jetstream enabled. To communicate with Nats server I use nats.net 2.5.7 and cli 0.1.6.
Even during a modest load on the server, a pull consumer can intermittently skip messages which match its filter criteria. I suspect that the issue is on the server side (specifically in the consumers logic) as it was never observed when a wildcard subject is removed from the filter.
Also to make sure that the issue isn't in the client library or application code I created 2 subscriptions using CLI, one for the subject of the interest and another one using the internal subscription of the consumer. As such I was able to see when the messages are delivered via both Core Nats and Jetstream.
In case of the failed run, I don't see the messages coming into the internal consumer subscription as well as I don't see records in the nats server logs which would indicate that the message was sent to the destination(e.g. HMSG TR.Subject.Service.Env.ID.214 1 $JS.ACK.Stream1.Consumer1.1.14848.33...)
Server mappings:
TR.Subject.Incoming TR.Subject.Service
TR.Subject.Incoming.> TR.Subject.Service.>
Stream info:
Information for Stream Stream1 created 2025-05-25 13:51:07
Subjects: TR.Subject.>, TR.Subject2.>, TR.Subject3.>,...
Replicas: 1
Storage: File
Options:
Retention: Limits
Acknowledgments: true
Discard Policy: Old
Duplicate Window: 2m0s
Direct Get: true
Allows Msg Delete: true
Allows Purge: true
Allows Rollups: false
Limits:
Maximum Messages: unlimited
Maximum Per Subject: unlimited
Maximum Bytes: unlimited
Maximum Age: unlimited
Maximum Message Size: 32 MiB
Maximum Consumers: unlimited
Metadata:
_nats.level: 1
_nats.req.level: 0
_nats.ver: 2.11.1
State:
Messages: 15,192
Bytes: 2.6 GiB
First Sequence: 331 @ 2025-05-25 15:42:43
Last Sequence: 15,522 @ 2025-05-27 20:04:08
Active Consumers: 16
Number of Subjects: 17
Consumer info:
Information for Consumer Stream1 > Consumer1 created 2025-05-26T16:18:27-04:00
Configuration:
Name: Consumer1
Pull Mode: true
Filter Subjects: TR.Subject.Service.Env.ID.214, TR.Subject.Service.Env.ID.214.>
Deliver Policy: All
Ack Policy: Explicit
Ack Wait: 1h0m0s
Replay Policy: Instant
Max Ack Pending: 1,000
Max Waiting Pulls: 512
Metadata:
_nats.ver: 2.11.1
_nats.level: 1
_nats.req.level: 0
State:
Last Delivered Message: Consumer sequence: 33 Stream sequence: 15,528 Last delivery: 3h34m47s ago
Acknowledgment Floor: Consumer sequence: 33 Stream sequence: 14,851 Last Ack: 3h34m46s ago
Outstanding Acks: 0 out of maximum 1,000
Redelivered Messages: 0
Unprocessed Messages: 0
Waiting Pulls: 1 of maximum 512
The application Log:
2025-05-27 10:19:58,225 [13] DEBUG MessageBroker.Messaging.Nats.AsyncNatsConsumer - Starting Nats subscriber loop for Consumer. ConsumerName="Consumer1"
2025-05-27 10:19:58,279 [13] DEBUG MessageBroker.Messaging.Nats.NatsNetLoggerFactory - Consume setup maxMsgs:1000, thresholdMsgs:500, maxBytes:0, thresholdBytes:0, expires:00:00:30, idle:00:00:15, hbTimeout:30000
2025-05-27 10:19:58,282 [13] DEBUG MessageBroker.Messaging.Nats.NatsNetLoggerFactory - New subscription _INBOX.ByclVW6pvtMaAmrtLXvlgW/2
2025-05-27 10:19:58,284 [13] DEBUG MessageBroker.Messaging.Nats.NatsNetLoggerFactory - Sending pull request for init 1000, 0
Failed run:
Core Nats subscription output(command:nats sub TR.Subject.Service.Env.ID.214):
[#18] Received on "TR.Subject.Service.Env.ID.214" with reply "_INBOX.fSoAHgIliLoLsIMwG1nWF0.Z3rnCv5EJuVQ5kYJGZscTm"
MESSAGE_ID: 66b7b127-c17c-4e13-ae51-c8c4071683d4
JMSTimestamp: 1748376789400
JMSType: JMSType1
MESSAGE_INTENT: Send
Content-Encoding: Plain
Nats-Msg-Id: 66b7b127-c17c-4e13-ae51-c8c4071683d4
The Jetstream consumer's subscription output(command: nats sub _INBOX.ByclVW6pvtMaAmrtLXvlgW):
[#356] Received on "_INBOX.ByclVW6pvtMaAmrtLXvlgW"
Nats-Pending-Messages: 1000
Nats-Pending-Bytes: 0
Status: 408
Description: Request Timeout
nil body
[#357] Received on "_INBOX.ByclVW6pvtMaAmrtLXvlgW"
Nats-Pending-Bytes: 0
Status: 408
Description: Request Timeout
Nats-Pending-Messages: 1000
nil body
Server output:
[9912] 2025/05/27 15:37:39.698867 [TRC] 10.XX.XX.215:64045 - cid:37 - ->> [HMSG _INBOX.ByclVW6pvtMaAmrtLXvlgW 1 84 84]
[9912] 2025/05/27 15:37:39.698867 [TRC] 10.YY.YY.122:52005 - cid:58 - ->> [HMSG _INBOX.ByclVW6pvtMaAmrtLXvlgW 2 84 84]
[9912] 2025/05/27 15:37:39.698867 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- [PUB $JS.API.CONSUMER.MSG.NEXT.Stream1.Consumer1 _INBOX.ByclVW6pvtMaAmrtLXvlgW 65]
[9912] 2025/05/27 15:37:39.698867 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- MSG_PAYLOAD: ["{\"expires\":30000000000,\"batch\":1000,\"idle_heartbeat\":15000000000}"]
[9912] 2025/05/27 15:38:06.693931 [TRC] 10.YY.YY.122:52302 - cid:63 - <<- [HPUB TR.Subject.Incoming.Env.ID.214 _INBOX.Xv10eHg63b6WtSFbXgabrV.Yv0A7yILqweQWjvNcBznNf 272 704]
[9912] 2025/05/27 15:38:06.693931 [TRC] 10.YY.YY.122:52302 - cid:63 - <<- [MAPPING TR.Subject.Incoming.Env.ID.214 -> TR.Subject.Service.Env.ID.214]
[9912] 2025/05/27 15:38:06.693931 [TRC] 10.YY.YY.122:52302 - cid:63 - <<- MSG_PAYLOAD: ["NATS/1.0\r\nContent-Encoding: Plain\r\nNats-Msg-Id: 66b7b127-c17c-4e13-ae51-c8c4071683d4\r\nMESSAGE_ID: 66b7b127-c17c-4e13-ae51-c8c4071683d4\r\nJMSTimestamp: 1748374686696\r\nJMSType: JMSType1\r\nMESSAGE_INTENT: Send \r\n\r\n<<Payload was here>"]
[9912] 2025/05/27 15:38:06.693931 [TRC] 10.XX.XX.215:64046 - cid:38 - ->> [HMSG TR.Subject.Service.Env.ID.214 1 _INBOX.Xv10eHg63b6WtSFbXgabrV.Yv0A7yILqweQWjvNcBznNf 272 704]
[9912] 2025/05/27 15:38:06.693931 [TRC] 10.YY.YY.122:52302 - cid:63 - ->> [MSG _INBOX.Xv10eHg63b6WtSFbXgabrV.Yv0A7yILqweQWjvNcBznNf 1 36]
[9912] 2025/05/27 15:38:09.705871 [TRC] 10.XX.XX.215:64045 - cid:37 - ->> [HMSG _INBOX.ByclVW6pvtMaAmrtLXvlgW 1 84 84]
[9912] 2025/05/27 15:38:09.705871 [TRC] 10.YY.YY.122:52005 - cid:58 - ->> [HMSG _INBOX.ByclVW6pvtMaAmrtLXvlgW 2 84 84]
[9912] 2025/05/27 15:38:09.705871 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- [PUB $JS.API.CONSUMER.MSG.NEXT.Stream1.Consumer1 _INBOX.ByclVW6pvtMaAmrtLXvlgW 65]
[9912] 2025/05/27 15:38:09.705871 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- MSG_PAYLOAD: ["{\"expires\":30000000000,\"batch\":1000,\"idle_heartbeat\":15000000000}"]
[9912] 2025/05/27 15:38:09.991667 [TRC] 10.YY.YY.122:52008 - cid:60 - ->> [HMSG _INBOX.LsDdj62HSeMcM7gYELrwqT 35813 81 81]
Expected behavior
An example of the successful run:
Core Nats subscription output(command:nats sub TR.Subject.Service.Env.ID.214):
[#21] Received on "TR.Subject.Service.Env.ID.214" with reply "_INBOX.GOevmdVLFLNeQgYo1MGQDm.EQiMsMoj9JcF13DbaWulsb"
MESSAGE_INTENT: Send
Content-Encoding: Plain
Nats-Msg-Id: 9a9ebcf4-943d-4b6e-a404-50761531240a
MESSAGE_ID: 9a9ebcf4-943d-4b6e-a404-50761531240a
JMSTimestamp: 1748377886704
JMSType: JMSType1
The Jetstream consumer's subscription output(command: nats sub _INBOX.ByclVW6pvtMaAmrtLXvlgW):
[#364] Received JetStream message: consumer: Stream1 > Consumer1 / subject: TR.Subject.Service.Env.ID.214 / delivered: 1 / consumer seq: 33 / stream seq: 14848
JMSTimestamp: 1748377886704
JMSType: JMSType1
MESSAGE_INTENT: Send
Content-Encoding: Plain
Nats-Msg-Id: 9a9ebcf4-943d-4b6e-a404-50761531240a
MESSAGE_ID: 9a9ebcf4-943d-4b6e-a404-50761531240a
Server output:
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.YY.YY.122:53766 - cid:201 - <<- [HPUB TR.Subject.Incoming.Env.ID.214 _INBOX.GOevmdVLFLNeQgYo1MGQDm.EQiMsMoj9JcF13DbaWulsb 272 704]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.YY.YY.122:53766 - cid:201 - <<- [MAPPING TR.Subject.Incoming.Env.ID.214 -> TR.Subject.Service.Env.ID.214]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.YY.YY.122:53766 - cid:201 - <<- MSG_PAYLOAD: ["NATS/1.0\r\nContent-Encoding: Plain\r\nNats-Msg-Id: 9a9ebcf4-943d-4b6e-a404-50761531240a\r\nMESSAGE_ID: 9a9ebcf4-943d-4b6e-a404-50761531240a\r\nJMSTimestamp: 1748377886704\r\nJMSType: JMSType1\r\nMESSAGE_INTENT: Send\r\n\r\n\<Payload was here>"]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.XX.XX.215:64046 - cid:38 - ->> [HMSG TR.Subject.Service.Env.ID.214 1 _INBOX.GOevmdVLFLNeQgYo1MGQDm.EQiMsMoj9JcF13DbaWulsb 272 704]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.YY.YY.122:53766 - cid:201 - ->> [MSG _INBOX.GOevmdVLFLNeQgYo1MGQDm.EQiMsMoj9JcF13DbaWulsb 1 36]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.XX.XX.215:64045 - cid:37 - ->> [HMSG TR.Subject.Service.Env.ID.214 1 $JS.ACK.Stream1.Consumer1.1.14848.33.1748377886709172600.0 272 704]
[9912] 2025/05/27 16:31:26.709172 [TRC] 10.YY.YY.122:52005 - cid:58 - ->> [HMSG TR.Subject.Service.Env.ID.214 2 $JS.ACK.Stream1.Consumer1.1.14848.33.1748377886709172600.0 272 704]
[9912] 2025/05/27 16:31:27.056709 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- [PUB $JS.ACK.Stream1.Consumer1.1.14848.33.1748377886709172600.0 4]
[9912] 2025/05/27 16:31:27.056709 [TRC] 10.YY.YY.122:52005 - cid:58 - <<- MSG_PAYLOAD: ["+ACK"]
Server and client version
Couldn't yet reproduce it in 2.11.4 but I also wasn't able to find an existing defect with a similar behavior
Host environment
No response
Steps to reproduce
No response