search

nats-io / nats-server

High-Performance server for NATS.io, the cloud and edge native messaging system.
https://nats.io
Apache License 2.0
15.49k stars 1.38k forks source link

nil pointer dereference in simple stream usage #3657

Closed jdhenke closed 1 year ago

jdhenke commented 1 year ago

Defect

Make sure that these boxes are checked before submitting your issue -- thank you!

Versions of nats-server and affected client libraries used:

Server:

$ docker run nats:2.9.7 -DV
[1] 2022/11/21 21:32:26.630403 [INF] Starting nats-server
[1] 2022/11/21 21:32:26.630476 [INF]   Version:  2.9.7
[1] 2022/11/21 21:32:26.630479 [INF]   Git:      [1e76678]
[1] 2022/11/21 21:32:26.630481 [DBG]   Go build: go1.19.3
[1] 2022/11/21 21:32:26.630483 [INF]   Name:     NB77E5IAHUPZ3QVEWVN5G4CIM6H5TAX6IJOCJO6GRBDEQ73HOZNIC7WN
[1] 2022/11/21 21:32:26.630488 [INF]   ID:       NB77E5IAHUPZ3QVEWVN5G4CIM6H5TAX6IJOCJO6GRBDEQ73HOZNIC7WN
[1] 2022/11/21 21:32:26.630539 [DBG] Created system account: "$SYS"
[1] 2022/11/21 21:32:26.633964 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2022/11/21 21:32:26.633999 [DBG] Get non local IPs for "0.0.0.0"
[1] 2022/11/21 21:32:26.634317 [DBG]   ip=172.17.0.3
[1] 2022/11/21 21:32:26.634383 [INF] Server is ready
[1] 2022/11/21 21:32:26.634627 [DBG] maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined

Client:

$ nats --version
v0.0.35

OS/Container environment:

Docker container nats:2.9.7

Steps or code to reproduce the issue:

Store this as config.json 

{
  "name": "foo",
  "subjects": [
    "bar"
  ],
  "retention": "limits",
  "max_consumers": -1,
  "max_msgs_per_subject": -1,
  "max_msgs": -1,
  "max_bytes": -1,
  "max_age": 0,
  "max_msg_size": -1,
  "storage": "file",
  "discard": "old",
  "num_replicas": 1,
  "duplicate_window": 120000000000,
  "sealed": false,
  "deny_delete": false,
  "deny_purge": false,
  "allow_rollup_hdrs": false,
  "allow_direct": false,
  "mirror_direct": false
}

Run the following:

# step 1
docker run -d -p 4222:4222 --name nats nats:2.9.7 -js
# step 2
nats stream add --config=config.json
# step 3
nats pub bar baz
# step 4
nats stream view foo
# step 5
docker logs nats

Expected result:

You see baz in the stream foo and the log show no errors.

⚠️ NOTE: this non-deterministically succeeds/fails; here is an example success that works as expected, same steps:

$ docker run -d -p 4222:4222 --name nats nats:2.9.7 -js
8b9cbbb0e65c4d26e4ec42f624f70104ec1bd65049a8ac5b6d5b1d6f6ff6ab59
$ nats stream add --config=config.json                 
Stream foo was created

Information for Stream foo created 2022-11-21 15:00:13

             Subjects: bar
             Replicas: 1
              Storage: File

Options:

            Retention: Limits
     Acknowledgements: true
       Discard Policy: Old
     Duplicate Window: 2m0s
    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: unlimited
    Maximum Consumers: unlimited

State:

             Messages: 0
                Bytes: 0 B
             FirstSeq: 0
              LastSeq: 0
     Active Consumers: 0
$ nats pub bar baz                                     
15:00:16 Published 3 bytes to "bar"
$ nats stream view foo                                 
[1] Subject: bar Received: 2022-11-21T15:00:16-07:00

baz

15:00:17 Reached apparent end of data
$ docker logs nats                                     
[1] 2022/11/21 22:00:11.105470 [INF] Starting nats-server
[1] 2022/11/21 22:00:11.105608 [INF]   Version:  2.9.7
[1] 2022/11/21 22:00:11.105614 [INF]   Git:      [1e76678]
[1] 2022/11/21 22:00:11.105615 [INF]   Name:     NBWM3MUKRUDUXEVQDTW27IHTBWEVBCXDCMF2MC6ONGE3SMGNURP2B67H
[1] 2022/11/21 22:00:11.105620 [INF]   Node:     55l7Yt1s
[1] 2022/11/21 22:00:11.105621 [INF]   ID:       NBWM3MUKRUDUXEVQDTW27IHTBWEVBCXDCMF2MC6ONGE3SMGNURP2B67H
[1] 2022/11/21 22:00:11.106623 [INF] Starting JetStream
[1] 2022/11/21 22:00:11.107777 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2022/11/21 22:00:11.107804 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2022/11/21 22:00:11.107806 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2022/11/21 22:00:11.107807 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2022/11/21 22:00:11.107808 [INF] 
[1] 2022/11/21 22:00:11.107809 [INF]          https://docs.nats.io/jetstream
[1] 2022/11/21 22:00:11.107810 [INF] 
[1] 2022/11/21 22:00:11.107811 [INF] ---------------- JETSTREAM ----------------
[1] 2022/11/21 22:00:11.107814 [INF]   Max Memory:      5.83 GB
[1] 2022/11/21 22:00:11.107815 [INF]   Max Storage:     24.96 GB
[1] 2022/11/21 22:00:11.107816 [INF]   Store Directory: "/tmp/nats/jetstream"
[1] 2022/11/21 22:00:11.107818 [INF] -------------------------------------------
[1] 2022/11/21 22:00:11.108327 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2022/11/21 22:00:11.108632 [INF] Server is ready

Actual result:

⚠️ NOTE: Again, calling out that this non-deterministically succeeds/fails. Here's an example of it failing:

$ docker run -d -p 4222:4222 --name nats nats:2.9.7 -js
c6ee43c70e3f31091c4b7dda17631f62cf81ce68a5b1c23c67cefa96fe62a55f
$ nats stream add --config=config.json                 
Stream foo was created

Information for Stream foo created 2022-11-21 15:00:34

             Subjects: bar
             Replicas: 1
              Storage: File

Options:

            Retention: Limits
     Acknowledgements: true
       Discard Policy: Old
     Duplicate Window: 2m0s
    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: unlimited
    Maximum Consumers: unlimited

State:

             Messages: 0
                Bytes: 0 B
             FirstSeq: 0
              LastSeq: 0
     Active Consumers: 0
$ nats pub bar baz                                     
15:00:36 Published 3 bytes to "bar"
$ nats stream view foo                                 
[1] Subject: bar Received: 2022-11-21T15:00:36-07:00

baz

15:00:38 Reached apparent end of data
15:00:38 Disconnected due to: EOF, will attempt reconnect
$ docker logs nats                                     
[1] 2022/11/21 22:00:33.147577 [INF] Starting nats-server
[1] 2022/11/21 22:00:33.147691 [INF]   Version:  2.9.7
[1] 2022/11/21 22:00:33.147693 [INF]   Git:      [1e76678]
[1] 2022/11/21 22:00:33.147695 [INF]   Name:     NCHLR747DO434WRHDFZIRY3HGYPMJVH57A4LJBH7EJ2YC2FGD3BVNDDF
[1] 2022/11/21 22:00:33.147699 [INF]   Node:     aCsxkTp9
[1] 2022/11/21 22:00:33.147700 [INF]   ID:       NCHLR747DO434WRHDFZIRY3HGYPMJVH57A4LJBH7EJ2YC2FGD3BVNDDF
[1] 2022/11/21 22:00:33.148125 [INF] Starting JetStream
[1] 2022/11/21 22:00:33.148451 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2022/11/21 22:00:33.148455 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2022/11/21 22:00:33.148456 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2022/11/21 22:00:33.148457 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2022/11/21 22:00:33.148458 [INF] 
[1] 2022/11/21 22:00:33.148459 [INF]          https://docs.nats.io/jetstream
[1] 2022/11/21 22:00:33.148460 [INF] 
[1] 2022/11/21 22:00:33.148461 [INF] ---------------- JETSTREAM ----------------
[1] 2022/11/21 22:00:33.148463 [INF]   Max Memory:      5.83 GB
[1] 2022/11/21 22:00:33.148465 [INF]   Max Storage:     24.96 GB
[1] 2022/11/21 22:00:33.148466 [INF]   Store Directory: "/tmp/nats/jetstream"
[1] 2022/11/21 22:00:33.148467 [INF] -------------------------------------------
[1] 2022/11/21 22:00:33.149756 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2022/11/21 22:00:33.150165 [INF] Server is ready
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x7b707a]

goroutine 30 [running]:
github.com/nats-io/nats-server/v2/server.(*consumer).suppressDeletion(0xc00036b680)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:3138 +0xba
github.com/nats-io/nats-server/v2/server.(*consumer).processInboundAcks(0xc00036b680, 0xc0000e8e40)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:3118 +0x1d8
created by github.com/nats-io/nats-server/v2/server.(*consumer).setLeader
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:1069 +0xb0c

To call out the unexpected pieces:

Step 4 shows this output:

⚠️ Disconnected due to: EOF, will attempt reconnect is unexpected

$ nats stream view foo
[1] Subject: bar Received: 2022-11-21T14:39:03-07:00

baz

14:39:05 Reached apparent end of data
14:39:05 Disconnected due to: EOF, will attempt reconnect

Step 5 shows this output showing the server has crashed due to a nil pointer dereference.

⚠️ panic: runtime error: invalid memory address or nil pointer dereference is unexpected

$ docker logs nats
[1] 2022/11/21 21:38:52.685141 [INF] Starting nats-server
[1] 2022/11/21 21:38:52.685266 [INF]   Version:  2.9.7
[1] 2022/11/21 21:38:52.685276 [INF]   Git:      [1e76678]
[1] 2022/11/21 21:38:52.685280 [INF]   Name:     NCODTBRWYKKQNPTQKU6T32Q257VEBF7JOUZOWSRGJQBE77XVDYWBJFML
[1] 2022/11/21 21:38:52.685302 [INF]   Node:     vlK9yvhk
[1] 2022/11/21 21:38:52.685304 [INF]   ID:       NCODTBRWYKKQNPTQKU6T32Q257VEBF7JOUZOWSRGJQBE77XVDYWBJFML
[1] 2022/11/21 21:38:52.686761 [INF] Starting JetStream
[1] 2022/11/21 21:38:52.690065 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[1] 2022/11/21 21:38:52.690092 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[1] 2022/11/21 21:38:52.690095 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[1] 2022/11/21 21:38:52.690096 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[1] 2022/11/21 21:38:52.690097 [INF] 
[1] 2022/11/21 21:38:52.690098 [INF]          https://docs.nats.io/jetstream
[1] 2022/11/21 21:38:52.690099 [INF] 
[1] 2022/11/21 21:38:52.690100 [INF] ---------------- JETSTREAM ----------------
[1] 2022/11/21 21:38:52.690104 [INF]   Max Memory:      5.83 GB
[1] 2022/11/21 21:38:52.690106 [INF]   Max Storage:     24.96 GB
[1] 2022/11/21 21:38:52.690108 [INF]   Store Directory: "/tmp/nats/jetstream"
[1] 2022/11/21 21:38:52.690109 [INF] -------------------------------------------
[1] 2022/11/21 21:38:52.692415 [INF] Listening for client connections on 0.0.0.0:4222
[1] 2022/11/21 21:38:52.693190 [INF] Server is ready
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x7b707a]

goroutine 82 [running]:
github.com/nats-io/nats-server/v2/server.(*consumer).suppressDeletion(0xc0000af200)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:3138 +0xba
github.com/nats-io/nats-server/v2/server.(*consumer).processInboundAcks(0xc0000af200, 0xc000074f00)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:3118 +0x1d8
created by github.com/nats-io/nats-server/v2/server.(*consumer).setLeader
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/consumer.go:1069 +0xb0c
derekcollison commented 1 year ago

ok I see what is going on, the ack is being processed after the consumer has been deleted in that instance. But as you point out only sometimes it will crash. For me took quite a bit of tries.