Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

expected sequence does not match store when using Nats-Msg-Id header #2242

Closed
krisdaniels opened this issue May 24, 2021 · 1 comment · Fixed by #2245
Closed

expected sequence does not match store when using Nats-Msg-Id header #2242

krisdaniels opened this issue May 24, 2021 · 1 comment · Fixed by #2245
Assignees
@derekcollison
Projects
JetStream 2.3 Planning

Comments

@krisdaniels
Copy link

When using a msg id to prevent duplicates, an error is always returned when sending a non duplicate after having received a duplicate ack result :

docker run -ti --rm --network host natsio/nats-box

nats str add ORDERS --subjects "ORDERS.*" --ack --max-msgs=-1 --max-bytes=-1 --max-age=1y --storage file --retention limits --max-msg-size=-1 --discard old --dupe-window="0s" --replicas 2
nats con add ORDERS NEW --filter ORDERS.new --ack explicit --pull --deliver all --sample 100 --max-deliver 20 --replay instant --max-pending 20

nats req -H Nats-Msg-Id:1 ORDERS.new hello1 
nats req -H Nats-Msg-Id:1 ORDERS.new hello2 # duplicate
nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # new msg always fails after duplicate
nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # retry 1 fails
nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # retry 2 succeeds

First message + duplicate :

# nats req -H Nats-Msg-Id:1 ORDERS.new hello1 

05:16:03 Sending request on "ORDERS.new"
05:16:03 Received on "_INBOX.r0yfSLDniVtFWbJXzrdkyZ.OGFSlLFI" rtt 1.003804ms
{"stream":"ORDERS","seq":1}

# nats req -H Nats-Msg-Id:1 ORDERS.new hello2 # duplicate

05:16:03 Sending request on "ORDERS.new"
05:16:03 Received on "_INBOX.Gu8EQT3FXwoZTn2pXW8oRb.MPEuuDBY" rtt 973.104µs
{"stream":"ORDERS","seq":1,"duplicate": true}

First attempt of new message after duplicate

# nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # new msg always fails after duplicate

05:16:03 Sending request on "ORDERS.new"
05:16:03 Received on "_INBOX.9MXKkqfTzruzga2f9zztXo.nRG0SrMJ" rtt 1.058504ms
{"error":{"code":503,"description":"expected sequence does not match store"},"stream":"ORDERS","seq":0}

Second attempt of new message after duplicate

# nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # retry 1 fails

05:16:03 Sending request on "ORDERS.new"
05:16:03 Received on "_INBOX.oNSsmTtzsFQ2kQKyypIpAp.HStDnu1s" rtt 1.014404ms
{"error":{"code":503,"description":"expected stream sequence does not match"},"stream":"ORDERS","seq":0}

Third attempt of new message after duplicate

# nats req -H Nats-Msg-Id:2 ORDERS.new hello3 # retry 2 succeeds

05:16:04 Sending request on "ORDERS.new"
05:16:04 Received on "_INBOX.9V2tVYbsCj5QAYZUdglPSz.vRWPMBoS" rtt 946.503µs
{"stream":"ORDERS","seq":2}

Configs :

server_name: n1-c1
port: 4221
monitor_port: 8221
jetstream {
   store_dir: /nats/data1
}
cluster {
  name: c1
  port: 6221
  authorization {
    user: ruser
    password: T0pS3cr3t
    timeout: 2
  }
  routes = [
    nats-route://ruser:T0pS3cr3t@localhost:6222
    nats-route://ruser:T0pS3cr3t@localhost:6223
  ]
}

#######################################################
server_name: n2-c1
port: 4222
monitor_port: 8222
jetstream {
   store_dir: /nats/data2
}
cluster {
  name: c1
  port: 6222
  authorization {
    user: ruser
    password: T0pS3cr3t
    timeout: 2
  }
  routes = [
    nats-route://ruser:T0pS3cr3t@localhost:6221
    nats-route://ruser:T0pS3cr3t@localhost:6223
  ]
}

#######################################################
server_name: n3-c1
port: 4223
monitor_port: 8223
jetstream {
   store_dir: /nats/data3
}
cluster {
  name: c1
  port: 6223
  authorization {
    user: ruser
    password: T0pS3cr3t
    timeout: 2
  }
  routes = [
    nats-route://ruser:T0pS3cr3t@localhost:6221
    nats-route://ruser:T0pS3cr3t@localhost:6222
  ]
}

Docker images used and start commands:


docker run --rm --network host --name n1c1 -ti -v /opt/nats/n1:/nats nats:2.2.5-scratch -js -c /nats/nats-server-js.conf
docker run --rm --network host --name n2c1 -ti -v /opt/nats/n2:/nats nats:2.2.5-scratch -js -c /nats/nats-server-js.conf
docker run --rm --network host --name n3c1 -ti -v /opt/nats/n3:/nats nats:2.2.5-scratch -js -c /nats/nats-server-js.conf

Logs :


# nats str add ORDERS --subjects "ORDERS.*" --ack --max-msgs=-1 --max-bytes=-1 --max-age=1y --storage file --retention limits --max-msg-size=-1 --discard old --dupe-window="0s" --replicas 2
Information for Stream ORDERS created 2021-05-24T05:16:02Z

Configuration:

             Subjects: ORDERS.*
     Acknowledgements: true
            Retention: File - Limits
             Replicas: 2
       Discard Policy: Old
     Duplicate Window: 2m0s
     Maximum Messages: unlimited
        Maximum Bytes: unlimited
          Maximum Age: 1y0d0h0m0s
 Maximum Message Size: unlimited
    Maximum Consumers: unlimited

Cluster Information:

                 Name: c1
               Leader: n2-c1
              Replica: n1-c1, current, seen 0.00s ago

State:

             Messages: 0
                Bytes: 0 B
             FirstSeq: 0
              LastSeq: 0
     Active Consumers: 0

# nats con add ORDERS NEW --filter ORDERS.new --ack explicit --pull --deliver all --sample 100 --max-deliver 20 --replay instant --max-pending 20
Information for Consumer ORDERS > NEW created 2021-05-24T05:16:02Z

Configuration:

        Durable Name: NEW
           Pull Mode: true
      Filter Subject: ORDERS.new
         Deliver All: true
          Ack Policy: Explicit
            Ack Wait: 30s
       Replay Policy: Instant
  Maximum Deliveries: 20
       Sampling Rate: 100
     Max Ack Pending: 20

Cluster Information:

                Name: c1
              Leader: n2-c1
             Replica: n1-c1, current, seen 0.00s ago

State:

   Last Delivered Message: Consumer sequence: 0 Stream sequence: 0
     Acknowledgment floor: Consumer sequence: 0 Stream sequence: 0
         Outstanding Acks: 0 out of maximum 20
     Redelivered Messages: 0
     Unprocessed Messages: 0    

# n1c1
[1] 2021/05/24 05:15:45.501791 [INF] Starting nats-server
[1] 2021/05/24 05:15:45.501840 [INF]   Version:  2.2.5
[1] 2021/05/24 05:15:45.501850 [INF]   Git:      [b7e1f66]
[1] 2021/05/24 05:15:45.501852 [INF]   Name:     n1-c1
[1] 2021/05/24 05:15:45.501856 [INF]   Node:     oP5LzZ64
[1] 2021/05/24 05:15:45.501858 [INF]   ID:       NA2LUWZUM4K5LXSTMBVJBVV2BDHOQUM2RZVTOFV2KCXEECCO7NWJRMW7
[1] 2021/05/24 05:15:45.501866 [INF] Using configuration file: /nats/nats-server-js.conf
[1] 2021/05/24 05:15:45.503345 [INF] Starting JetStream
[1] 2021/05/24 05:15:45.503687 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2021/05/24 05:15:45.503699 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2021/05/24 05:15:45.503702 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2021/05/24 05:15:45.503704 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2021/05/24 05:15:45.503705 [INF] 
[1] 2021/05/24 05:15:45.503707 [INF]          https://docs.nats.io/jetstream
[1] 2021/05/24 05:15:45.503709 [INF] 
[1] 2021/05/24 05:15:45.503711 [INF] ---------------- JETSTREAM ----------------
[1] 2021/05/24 05:15:45.503716 [INF]   Max Memory:      47.11 GB
[1] 2021/05/24 05:15:45.503719 [INF]   Max Storage:     71.63 GB
[1] 2021/05/24 05:15:45.503721 [INF]   Store Directory: "/nats/data1/jetstream"
[1] 2021/05/24 05:15:45.503722 [INF] -------------------------------------------
[1] 2021/05/24 05:15:45.503954 [INF] Starting JetStream cluster
[1] 2021/05/24 05:15:45.503966 [INF] Creating JetStream metadata controller
[1] 2021/05/24 05:15:45.504617 [INF] JetStream cluster bootstrapping
[1] 2021/05/24 05:15:45.507293 [INF] Starting http monitor on 0.0.0.0:8221
[1] 2021/05/24 05:15:45.507364 [INF] Listening for client connections on 0.0.0.0:4221
[1] 2021/05/24 05:15:45.507844 [INF] Server is ready
[1] 2021/05/24 05:15:45.507878 [INF] Cluster name is c1
[1] 2021/05/24 05:15:45.507917 [INF] Listening for route connections on 0.0.0.0:6221
[1] 2021/05/24 05:15:45.508760 [ERR] Error trying to connect to route (attempt 1): dial tcp 127.0.0.1:6222: connect: connection refused
[1] 2021/05/24 05:15:45.508761 [ERR] Error trying to connect to route (attempt 1): dial tcp 127.0.0.1:6223: connect: connection refused
[1] 2021/05/24 05:15:45.834585 [INF] 127.0.0.1:55950 - rid:6 - Route connection created
[1] 2021/05/24 05:15:46.509468 [INF] 127.0.0.1:6222 - rid:7 - Route connection created
[1] 2021/05/24 05:15:46.509703 [INF] 127.0.0.1:6222 - rid:7 - Router connection closed: Duplicate Route
[1] 2021/05/24 05:15:46.763209 [INF] 127.0.0.1:55958 - rid:8 - Route connection created
[1] 2021/05/24 05:15:47.510420 [INF] 127.0.0.1:6223 - rid:9 - Route connection created
[1] 2021/05/24 05:15:47.510764 [INF] 127.0.0.1:6223 - rid:9 - Router connection closed: Duplicate Route
[1] 2021/05/24 05:16:03.262354 [ERR] JetStream failed to store a msg on stream '$G > ORDERS' -  expected sequence does not match store
[1] 2021/05/24 05:16:03.323042 [WRN] Got stream sequence mismatch for '$G > ORDERS'
[1] 2021/05/24 05:16:03.323801 [WRN] Resetting stream '$G > ORDERS'

# n2c1
[1] 2021/05/24 05:15:45.827275 [INF] Starting nats-server
[1] 2021/05/24 05:15:45.827315 [INF]   Version:  2.2.5
[1] 2021/05/24 05:15:45.827317 [INF]   Git:      [b7e1f66]
[1] 2021/05/24 05:15:45.827319 [INF]   Name:     n2-c1
[1] 2021/05/24 05:15:45.827340 [INF]   Node:     YGhnH3VX
[1] 2021/05/24 05:15:45.827343 [INF]   ID:       NBFT2DN4J3K7CHME3GZES5QSHJITYMPVGTUMMDQU7EIRUENXQZCXPWI4
[1] 2021/05/24 05:15:45.827356 [INF] Using configuration file: /nats/nats-server-js.conf
[1] 2021/05/24 05:15:45.828060 [INF] Starting JetStream
[1] 2021/05/24 05:15:45.828292 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2021/05/24 05:15:45.828306 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2021/05/24 05:15:45.828308 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2021/05/24 05:15:45.828309 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2021/05/24 05:15:45.828311 [INF] 
[1] 2021/05/24 05:15:45.828313 [INF]          https://docs.nats.io/jetstream
[1] 2021/05/24 05:15:45.828314 [INF] 
[1] 2021/05/24 05:15:45.828316 [INF] ---------------- JETSTREAM ----------------
[1] 2021/05/24 05:15:45.828321 [INF]   Max Memory:      47.11 GB
[1] 2021/05/24 05:15:45.828324 [INF]   Max Storage:     71.63 GB
[1] 2021/05/24 05:15:45.828326 [INF]   Store Directory: "/nats/data2/jetstream"
[1] 2021/05/24 05:15:45.828328 [INF] -------------------------------------------
[1] 2021/05/24 05:15:45.828611 [INF] Starting JetStream cluster
[1] 2021/05/24 05:15:45.828625 [INF] Creating JetStream metadata controller
[1] 2021/05/24 05:15:45.829221 [INF] JetStream cluster bootstrapping
[1] 2021/05/24 05:15:45.833060 [INF] Starting http monitor on 0.0.0.0:8222
[1] 2021/05/24 05:15:45.833112 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2021/05/24 05:15:45.833505 [INF] Server is ready
[1] 2021/05/24 05:15:45.833520 [INF] Cluster name is c1
[1] 2021/05/24 05:15:45.833560 [INF] Listening for route connections on 0.0.0.0:6222
[1] 2021/05/24 05:15:45.834256 [ERR] Error trying to connect to route (attempt 1): dial tcp 127.0.0.1:6223: connect: connection refused
[1] 2021/05/24 05:15:45.834573 [INF] 127.0.0.1:6221 - rid:6 - Route connection created
[1] 2021/05/24 05:15:46.509514 [INF] 127.0.0.1:51868 - rid:7 - Route connection created
[1] 2021/05/24 05:15:46.509817 [INF] 127.0.0.1:51868 - rid:7 - Router connection closed: Duplicate Route
[1] 2021/05/24 05:15:46.763164 [INF] 127.0.0.1:51872 - rid:8 - Route connection created
[1] 2021/05/24 05:15:46.834928 [INF] 127.0.0.1:6223 - rid:9 - Route connection created
[1] 2021/05/24 05:15:46.835205 [INF] 127.0.0.1:6223 - rid:9 - Router connection closed: Duplicate Route
[1] 2021/05/24 05:15:49.118613 [INF] JetStream cluster new metadata leader
[1] 2021/05/24 05:16:02.829210 [INF] JetStream cluster new stream leader for '$G > ORDERS'
[1] 2021/05/24 05:16:03.068025 [INF] JetStream cluster new consumer leader for '$G > ORDERS > NEW'
[1] 2021/05/24 05:16:03.262225 [ERR] JetStream failed to store a msg on stream '$G > ORDERS' -  expected sequence does not match store
[1] 2021/05/24 05:16:03.322924 [WRN] Got stream sequence mismatch for '$G > ORDERS'
[1] 2021/05/24 05:16:03.324023 [WRN] Resetting stream '$G > ORDERS'
[1] 2021/05/24 05:16:03.448718 [INF] JetStream cluster new stream leader for '$G > ORDERS'

# n3c1
[1] 2021/05/24 05:15:46.757037 [INF] Starting nats-server
[1] 2021/05/24 05:15:46.757084 [INF]   Version:  2.2.5
[1] 2021/05/24 05:15:46.757087 [INF]   Git:      [b7e1f66]
[1] 2021/05/24 05:15:46.757090 [INF]   Name:     n3-c1
[1] 2021/05/24 05:15:46.757094 [INF]   Node:     hxTjz3J4
[1] 2021/05/24 05:15:46.757096 [INF]   ID:       NAAIP3PK6PMRE5C5ZFKYMO4JHPZZ23VKIWOI7CNWHIDJL23H7ZXML3FD
[1] 2021/05/24 05:15:46.757104 [INF] Using configuration file: /nats/nats-server-js.conf
[1] 2021/05/24 05:15:46.757729 [INF] Starting JetStream
[1] 2021/05/24 05:15:46.757995 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2021/05/24 05:15:46.758008 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2021/05/24 05:15:46.758010 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2021/05/24 05:15:46.758012 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2021/05/24 05:15:46.758014 [INF] 
[1] 2021/05/24 05:15:46.758016 [INF]          https://docs.nats.io/jetstream
[1] 2021/05/24 05:15:46.758017 [INF] 
[1] 2021/05/24 05:15:46.758019 [INF] ---------------- JETSTREAM ----------------
[1] 2021/05/24 05:15:46.758023 [INF]   Max Memory:      47.11 GB
[1] 2021/05/24 05:15:46.758025 [INF]   Max Storage:     71.63 GB
[1] 2021/05/24 05:15:46.758027 [INF]   Store Directory: "/nats/data3/jetstream"
[1] 2021/05/24 05:15:46.758029 [INF] -------------------------------------------
[1] 2021/05/24 05:15:46.758188 [INF] Starting JetStream cluster
[1] 2021/05/24 05:15:46.758215 [INF] Creating JetStream metadata controller
[1] 2021/05/24 05:15:46.758801 [INF] JetStream cluster bootstrapping
[1] 2021/05/24 05:15:46.761751 [INF] Starting http monitor on 0.0.0.0:8223
[1] 2021/05/24 05:15:46.761801 [INF] Listening for client connections on 0.0.0.0:4223
[1] 2021/05/24 05:15:46.762113 [INF] Server is ready
[1] 2021/05/24 05:15:46.762130 [INF] Cluster name is c1
[1] 2021/05/24 05:15:46.762151 [INF] Listening for route connections on 0.0.0.0:6223
[1] 2021/05/24 05:15:46.763260 [INF] 127.0.0.1:6222 - rid:6 - Route connection created
[1] 2021/05/24 05:15:46.763315 [INF] 127.0.0.1:6221 - rid:7 - Route connection created
[1] 2021/05/24 05:15:46.835032 [INF] 127.0.0.1:39006 - rid:8 - Route connection created
[1] 2021/05/24 05:15:46.835251 [INF] 127.0.0.1:39006 - rid:8 - Router connection closed: Duplicate Route
[1] 2021/05/24 05:15:47.510547 [INF] 127.0.0.1:39008 - rid:9 - Route connection created
[1] 2021/05/24 05:15:47.510781 [INF] 127.0.0.1:39008 - rid:9 - Router connection closed: Duplicate Route
@ripienaar
Copy link
Contributor

I can confirm this is happening, and in a cluster even worse:

May 24 08:57:42 n2-sfo nats-server[1343]: [1] [INF] JetStream cluster new consumer leader for 'one > ORDERS_65 > C3'
May 24 08:57:44 n3-sfo nats-server[1362]: [1] [INF] JetStream cluster new consumer leader for 'one > ORDERS_14 > C1'
May 24 08:57:49 n3-nyc nats-server[1345]: [1] [ERR] JetStream failed to store a msg on stream 'one > ORDERS_1' -  expected sequence does not match store
May 24 08:57:49 n1-nyc nats-server[1346]: [1] [ERR] JetStream failed to store a msg on stream 'one > ORDERS_1' -  expected sequence does not match store
May 24 08:57:49 n2-nyc nats-server[1349]: [1] [ERR] JetStream failed to store a msg on stream 'one > ORDERS_1' -  expected sequence does not match store
May 24 08:57:49 n3-nyc nats-server[1345]: [1] [WRN] Got stream sequence mismatch for 'one > ORDERS_1'
May 24 08:57:49 n1-nyc nats-server[1346]: [1] [WRN] Got stream sequence mismatch for 'one > ORDERS_1'
May 24 08:57:49 n2-nyc nats-server[1349]: [1] [WRN] Got stream sequence mismatch for 'one > ORDERS_1'
May 24 08:57:49 n2-nyc nats-server[1349]: [1] [WRN] Resetting stream 'one > ORDERS_1'
May 24 08:57:49 n3-nyc nats-server[1345]: [1] [WRN] Resetting stream 'one > ORDERS_1'
May 24 08:57:49 n1-nyc nats-server[1346]: [1] [WRN] Resetting stream 'one > ORDERS_1'
May 24 08:57:51 n1-nyc nats-server[1346]: [1] [INF] JetStream cluster new stream leader for 'one > ORDERS_1'

This happens when I publish the first non dupe, definitely something bad giong on here.

@ripienaar ripienaar added this to To do in JetStream 2.3 Planning via automation May 24, 2021
@derekcollison derekcollison self-assigned this May 24, 2021
derekcollison added a commit that referenced this issue May 24, 2021
@derekcollison
Fix for #2242.
308355a 
When we had a duplicate detected in R>1 mode we set the skip sequence indicator but were not using that when dealing with underlying store.

Signed-off-by: Derek Collison <derek@nats.io>
@derekcollison derekcollison mentioned this issue May 24, 2021
Merged
JetStream 2.3 Planning automation moved this from To do to Done May 24, 2021
derekcollison added a commit that referenced this issue May 24, 2021
@derekcollison
Merge pull request #2245 from nats-io/msgid
11539ec 
[FIXED] #2242.
@bruth bruth removed the 🐞 bug label Aug 18, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@derekcollison derekcollison

Labels
None yet
Projects
No open projects
JetStream 2.3 Planning
Done
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[FIXED] #2242. nats-io/nats-server
4 participants
@ripienaar @derekcollison @bruth @krisdaniels