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.56k stars 1.39k forks source link

Runtime error on consumer checkPending #4262

Closed vxxvvxxv closed 1 year ago

vxxvvxxv commented 1 year ago

Defect

Versions of nats-server and affected client libraries used:

2.9.15

OS/Container environment:

MacOS 13.4 (22F66)

Steps or code to reproduce the issue:

Just waiting when nats stored about 4164339 items.

Actual result:

I use nats JetStream and got this message:

[38030] 2023/06/21 11:59:01.690361 [INF] Starting nats-server
[38030] 2023/06/21 11:59:01.690469 [INF]   Version:  2.9.15
[38030] 2023/06/21 11:59:01.690473 [INF]   Git:      [not set]
[38030] 2023/06/21 11:59:01.690475 [INF]   Name:     NAPM73PMM7PPSLKXJUUXZ56WTXCNLMBKIG3573WSGOXFAGLQF7OKMEQQ
[38030] 2023/06/21 11:59:01.690480 [INF]   Node:     8PEBxhOy
[38030] 2023/06/21 11:59:01.690482 [INF]   ID:       NAPM73PMM7PPSLKXJUUXZ56WTXCNLMBKIG3573WSGOXFAGLQF7OKMEQQ
[38030] 2023/06/21 11:59:01.690486 [WRN] Plaintext passwords detected, use nkeys or bcrypt
[38030] 2023/06/21 11:59:01.690782 [INF] Starting JetStream
[38030] 2023/06/21 11:59:01.692549 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[38030] 2023/06/21 11:59:01.692560 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[38030] 2023/06/21 11:59:01.692563 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[38030] 2023/06/21 11:59:01.692566 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[38030] 2023/06/21 11:59:01.692568 [INF]
[38030] 2023/06/21 11:59:01.692571 [INF]          https://docs.nats.io/jetstream
[38030] 2023/06/21 11:59:01.692573 [INF]
[38030] 2023/06/21 11:59:01.692575 [INF] ---------------- JETSTREAM ----------------
[38030] 2023/06/21 11:59:01.692581 [INF]   Max Memory:      6.00 GB
[38030] 2023/06/21 11:59:01.692585 [INF]   Max Storage:     35.80 GB
[38030] 2023/06/21 11:59:01.692590 [INF]   Store Directory: "/var/folders/v2/y4qq2b8j45j87h9t30sz59l00000gn/T/nats/jetstream"
[38030] 2023/06/21 11:59:01.692597 [INF] -------------------------------------------
[38030] 2023/06/21 11:59:01.693916 [INF]   Starting restore for stream '$G > DEALS'
[38030] 2023/06/21 11:59:01.696920 [INF]   Restored 0 messages for stream '$G > DEALS'
[38030] 2023/06/21 11:59:01.697258 [INF] Listening for client connections on 0.0.0.0:4222
[38030] 2023/06/21 11:59:01.697528 [INF] Server is ready
[38030] 2023/06/21 14:52:56.920113 [INF] 127.0.0.1:54783 - cid:47 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:02.586153 [INF] [::1]:55374 - cid:51 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:05.168553 [INF] 127.0.0.1:55377 - cid:54 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:08.361922 [INF] [::1]:55378 - cid:55 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:11.044808 [INF] [::1]:55379 - cid:56 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:14.019081 [INF] [::1]:55381 - cid:57 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:19:17.054710 [INF] 127.0.0.1:55382 - cid:58 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:20:26.724218 [INF] [::1]:55387 - cid:59 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
[38030] 2023/06/21 15:20:38.973821 [INF] 127.0.0.1:55409 - cid:60 - Slow Consumer Detected: MaxPending of 67108864 Exceeded
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x2 addr=0x20 pc=0x1043fee68]

goroutine 39648 [running]:
time.(*Timer).Reset(0x1400046cd88?, 0x0?)
    time/sleep.go:135 +0x18
github.com/nats-io/nats-server/v2/server.(*consumer).checkPending(0x1400046cd80)
    github.com/nats-io/nats-server/v2/server/consumer.go:3817 +0x590
created by time.goFunc
    time/sleep.go:176 +0x38

My stream information

Information for Stream DEALS created 2023-06-21 13:59:56

             Subjects: DEAL.>
             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: 3,885,334
                Bytes: 2.7 GiB
             FirstSeq: 1 @ 2023-06-21T08:24:41 UTC
              LastSeq: 3,885,334 @ 2023-06-21T09:20:42 UTC
     Active Consumers: 0
   Number of Subjects: 1
vxxvvxxv commented 1 year ago

Additional information with -DV flag:

[81155] 2023/06/21 15:34:49.438783 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845454.1210616.1687337875628835000.3039880 684]
[81155] 2023/06/21 15:34:49.441707 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478173.880951.1687337717897828000.3218553 4]
[81155] 2023/06/21 15:34:49.441713 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.441724 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478174.880952.1687337717897978000.3218553 4]
[81155] 2023/06/21 15:34:49.441725 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.441729 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478175.880953.1687337717898116000.3218553 4]
[81155] 2023/06/21 15:34:49.441730 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.441740 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478176.880954.1687337717898244000.3218553 4]
[81155] 2023/06/21 15:34:49.444008 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.444025 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478177.880955.1687337717898374000.3218553 4]
[81155] 2023/06/21 15:34:49.444027 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.444492 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478178.880956.1687337717898507000.3218553 4]
[81155] 2023/06/21 15:34:49.444501 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.444509 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478179.880957.1687337717898655000.3218553 4]
[81155] 2023/06/21 15:34:49.444511 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.444529 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478180.880958.1687337717898791000.3218553 4]
[81155] 2023/06/21 15:34:49.442867 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845455.1210617.1687337875629509000.3039879 684]
[81155] 2023/06/21 15:34:49.447264 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845456.1210618.1687337875630085000.3039878 684]
[81155] 2023/06/21 15:34:49.447274 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845457.1210619.1687337875630627000.3039877 684]
[81155] 2023/06/21 15:34:49.447278 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845458.1210620.1687337875631066000.3039876 684]
[81155] 2023/06/21 15:34:49.447280 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845459.1210621.1687337875631705000.3039875 684]
[81155] 2023/06/21 15:34:49.447282 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845460.1210622.1687337875632198000.3039874 684]
[81155] 2023/06/21 15:34:49.449574 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845461.1210623.1687337875633030000.3039873 684]
[81155] 2023/06/21 15:34:49.449580 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845462.1210624.1687337875633803000.3039872 684]
[81155] 2023/06/21 15:34:49.449582 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845463.1210625.1687337875634632000.3039871 684]
[81155] 2023/06/21 15:34:49.449584 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845464.1210626.1687337875635170000.3039870 684]
[81155] 2023/06/21 15:34:49.449587 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845465.1210627.1687337875635882000.3039869 684]
[81155] 2023/06/21 15:34:49.447839 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.451768 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478181.880959.1687337717898929000.3218553 4]
[81155] 2023/06/21 15:34:49.451774 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.451778 [TRC] 127.0.0.1:56114 - cid:7 - <<- [UNSUB 2 ]
[81155] 2023/06/21 15:34:49.451785 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845466.1210628.1687337875636531000.3039868 684]
[81155] 2023/06/21 15:34:49.453159 [TRC] 127.0.0.1:56114 - cid:7 - ->> [MSG RW-MANAGER.MT5-DEAL.> 2 $JS.ACK.DEALS.aY4RukeB.1.845467.1210629.1687337875637118000.3039867 684]
[81155] 2023/06/21 15:34:49.453173 [TRC] 127.0.0.1:56114 - cid:7 - <-> [DELSUB 2]
[81155] 2023/06/21 15:34:49.455618 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.ACK.DEALS.aY4RukeB.2.478182.880960.1687337717899051000.3218553 4]
[81155] 2023/06/21 15:34:49.455650 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: ["+ACK"]
[81155] 2023/06/21 15:34:49.455691 [TRC] 127.0.0.1:56114 - cid:7 - <<- [PUB $JS.API.CONSUMER.DELETE.DEALS.aY4RukeB _INBOX.SFiTWwyq48J1gVGOA4CTYD.eQKfmmW4 0]
[81155] 2023/06/21 15:34:49.455697 [TRC] 127.0.0.1:56114 - cid:7 - <<- MSG_PAYLOAD: [""]
[81155] 2023/06/21 15:34:49.573496 [TRC] JETSTREAM - <-> [DELSUB 1]
[81155] 2023/06/21 15:34:49.583798 [TRC] JETSTREAM - <-> [DELSUB 2]
[81155] 2023/06/21 15:34:49.583821 [TRC] JETSTREAM - <-> [DELSUB 45]
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x2 addr=0x20 pc=0x10068ee68]

goroutine 2793 [running]:
time.(*Timer).Reset(0x14000594908?, 0x18?)
    time/sleep.go:135 +0x18
github.com/nats-io/nats-server/v2/server.(*consumer).checkPending(0x14000594900)
    github.com/nats-io/nats-server/v2/server/consumer.go:3817 +0x590
created by time.goFunc
    time/sleep.go:176 +0x38
bruth commented 1 year ago

Thanks for the report @vxxvvxxv. Looking at the location of the panic, this may have been fixed in 2.9.16 (or later). 2.9.19 was released yesterday, so if you wouldn't mind updating to at least 2.9.16 and seeing if you still observe the issue that would be helpful.