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

jetStreamContext.Publish causes nats-server stack overflow error for Jetstream imported to different account #3397

Closed apis closed 2 years ago

apis commented 2 years ago

Defect

./nats-server -DV -c .\leaf.conf
[12284] 2022/08/24 11:14:01.897092 [INF] Starting nats-server
[12284] 2022/08/24 11:14:01.898237 [INF]   Version:  2.8.4
[12284] 2022/08/24 11:14:01.898237 [INF]   Git:      [66524ed]
[12284] 2022/08/24 11:14:01.898753 [DBG]   Go build: go1.17.10
[12284] 2022/08/24 11:14:01.898775 [INF]   Cluster:  leaf-server
[12284] 2022/08/24 11:14:01.898775 [INF]   Name:     leaf-server
[12284] 2022/08/24 11:14:01.898775 [INF]   Node:     1nWZLJcM
[12284] 2022/08/24 11:14:01.899292 [INF]   ID:       NAUQWGUKBJ4E6OK6NPEKN22QCKKGJR3QCR32P4WS3OPEA5QQENE7E7GQ
[12284] 2022/08/24 11:14:01.899363 [WRN] Plaintext passwords detected, use nkeys or bcrypt
[12284] 2022/08/24 11:14:01.899363 [INF] Using configuration file: .\leaf.conf
[12284] 2022/08/24 11:14:01.899916 [INF] Starting JetStream
[12284] 2022/08/24 11:14:01.899916 [DBG] JetStream creating dynamic configuration - 47.92 GB memory, 1.00 TB disk
[12284] 2022/08/24 11:14:01.901608 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[12284] 2022/08/24 11:14:01.901675 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[12284] 2022/08/24 11:14:01.901675 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[12284] 2022/08/24 11:14:01.901675 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[12284] 2022/08/24 11:14:01.901675 [INF]
[12284] 2022/08/24 11:14:01.902250 [INF]          https://docs.nats.io/jetstream
[12284] 2022/08/24 11:14:01.902250 [INF]
[12284] 2022/08/24 11:14:01.902250 [INF] ---------------- JETSTREAM ----------------
[12284] 2022/08/24 11:14:01.902250 [INF]   Max Memory:      47.92 GB
[12284] 2022/08/24 11:14:01.902832 [INF]   Max Storage:     1.00 TB
[12284] 2022/08/24 11:14:01.902832 [INF]   Store Directory: "store_leaf\jetstream"
[12284] 2022/08/24 11:14:01.902832 [INF]   Domain:          leaf
[12284] 2022/08/24 11:14:01.902832 [INF] -------------------------------------------
[12284] 2022/08/24 11:14:01.903362 [DBG]   Exports:
[12284] 2022/08/24 11:14:01.903362 [DBG]      $JS.API.>
[12284] 2022/08/24 11:14:01.903869 [DBG] Enabled JetStream for account "HUB_USER"
[12284] 2022/08/24 11:14:01.903897 [DBG]   Max Memory:      -1 B
[12284] 2022/08/24 11:14:01.903897 [DBG]   Max Storage:     -1 B
[12284] 2022/08/24 11:14:01.905694 [DBG] JetStream state for account "HUB_USER" recovered
[12284] 2022/08/24 11:14:01.905694 [DBG] Enabled JetStream for account "LEAF_USER"
[12284] 2022/08/24 11:14:01.905694 [DBG]   Max Memory:      -1 B
[12284] 2022/08/24 11:14:01.906203 [DBG]   Max Storage:     -1 B
[12284] 2022/08/24 11:14:01.907393 [DBG] JetStream state for account "LEAF_USER" recovered
[12284] 2022/08/24 11:14:01.908169 [DBG] Enabled JetStream for account "LEAF_INGRESS"
[12284] 2022/08/24 11:14:01.908169 [DBG]   Max Memory:      -1 B
[12284] 2022/08/24 11:14:01.908169 [DBG]   Max Storage:     -1 B
[12284] 2022/08/24 11:14:01.908724 [DBG] Recovering JetStream state for account "LEAF_INGRESS"
[12284] 2022/08/24 11:14:01.915459 [INF]   Restored 9 messages for stream 'LEAF_INGRESS > time-stream'
[12284] 2022/08/24 11:14:01.915459 [DBG] JetStream state for account "LEAF_INGRESS" recovered
[12284] 2022/08/24 11:14:01.918538 [INF] Listening for client connections on 0.0.0.0:34111
[12284] 2022/08/24 11:14:01.918538 [DBG] Get non local IPs for "0.0.0.0"
[12284] 2022/08/24 11:14:01.966054 [DBG]   ip=172.28.112.1
[12284] 2022/08/24 11:14:02.006058 [DBG]   ip=fd5e:9a9e:c5bd:10:7d3a:5371:a3e0:ce8e
[12284] 2022/08/24 11:14:02.006058 [DBG]   ip=fd5e:9a9e:c5bd:10:8c0:8d5d:bce6:90be
[12284] 2022/08/24 11:14:02.006626 [DBG]   ip=fd5e:9a9e:c5bd:10:15af:9cd6:b21c:e8e0
[12284] 2022/08/24 11:14:02.006626 [DBG]   ip=fd5e:9a9e:c5bd:10:d431:eca6:6145:dd68
[12284] 2022/08/24 11:14:02.006626 [DBG]   ip=192.168.1.190
[12284] 2022/08/24 11:14:02.046406 [DBG]   ip=172.31.144.1
[12284] 2022/08/24 11:14:02.059849 [DBG]   ip=172.25.0.1
[12284] 2022/08/24 11:14:02.059849 [INF] Server is ready
[12284] 2022/08/24 11:14:02.059849 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[12284] 2022/08/24 11:14:03.062257 [ERR] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 1): dial tcp 0.0.0.0:34333: i/o timeout 
accounts {
    SYS: {
        users: [{user: admin, password: admin}]
    }
    HUB_USER: {
        users: [{user: hub_user, password: hub_user}]
        exports: [
        ]
        jetstream: enabled
    }
    LEAF_USER: {
        users: [{user: leaf_user, password: leaf_user}]
        imports: [
            {service: {account: LEAF_INGRESS, subject: "time-stream"}}
            {service: {account: LEAF_INGRESS, subject: "_INBOX.>"}}
            {service: {account: LEAF_INGRESS, subject: "$JS.leaf.API.>"}, to: "JS.leaf_ingress@leaf.API.>" }
        ]
        jetstream: enabled
    }
    LEAF_INGRESS: {
        users: [{user: leaf_ingress, password: leaf_ingress}]
        exports: [
            {service: "time-stream", accounts: [LEAF_USER]}
            {service: "_INBOX.>", accounts: [LEAF_USER]}
            {service: "$JS.leaf.API.>", response_type: "stream", accounts: [LEAF_USER]}
        ]
        imports: [
        ]
        jetstream: enabled
    }
}

system_account: SYS

Main config

  port: 34111
server_name: leaf-server
jetstream {
    store_dir="./store_leaf"
    domain=leaf
}
leafnodes {
    remotes = [
        {
            urls: ["nats-leaf://leaf_ingress:leaf_ingress@0.0.0.0:34333"]
            account: "LEAF_INGRESS"
        }
    ]
}
include ./accounts_leaf.conf

Client App

 package main

import (
    "encoding/json"
    "github.com/nats-io/nats.go"
    log "github.com/sirupsen/logrus"
    "time"
)

const natsSubjectTimeStream = "time-stream"
const streamName = "time-stream"

func main() {
    natsUserUrl := "nats://leaf_user:leaf_user@127.0.0.1:34111"

    log.Infof("Connecting User to NATS '%s'", natsUserUrl)
    natsUserConnection, err := connectToNats(natsUserUrl, "Backend Service User Connection")
    if err != nil {
        log.Fatal(err)
    }

    defer func() {
        log.Info("Closing User NATS connection")
        natsUserConnection.Close()
    }()

    log.Print("getting JetStream context")
    jetStreamContext, err := natsUserConnection.JetStream(nats.APIPrefix("JS.leaf_ingress@leaf.API."))
    if err != nil {
        log.Fatal(err)
    }

    stream, err := jetStreamContext.StreamInfo(streamName)
    if err != nil {
        log.Print(err)
    }

    if stream == nil {
        log.Printf("Creating stream '%s' and subject '%s'", streamName, natsSubjectTimeStream)
        stream, err = jetStreamContext.AddStream(&nats.StreamConfig{
            Name:     streamName,
            Subjects: []string{natsSubjectTimeStream},
            Storage:  nats.FileStorage,
        })
        if err != nil {
            log.Print(err)
        }
    } else {
        log.Printf("Stream '%s' already exists", streamName)
    }

    log.Printf("Stream info: '%v'", stream)

    message := time.Now().Format(time.RFC3339)

    buffer, err := json.Marshal(message)
    if err != nil {
        log.Fatal(err)
    }

    log.Infof("Publishing TimeStream: %s", message)

    pubAck, err := jetStreamContext.Publish(natsSubjectTimeStream, buffer)
    if err != nil {
        log.Fatal(err)
    }

    log.Printf("Ack: '%v'", pubAck)

    //err = natsUserConnection.Publish(natsSubjectTimeStream, buffer)
    //if err != nil {
    //  log.Fatal(err)
    //}
}

func connectToNats(natsUserUrl string, connectionName string) (*nats.Conn, error) {
    options := nats.Options{
        Url:  natsUserUrl,
        Name: connectionName,
    }

    var natsConnection *nats.Conn
    var err error

    for index := 0; index < 5; index++ {
        if index > 0 {
            time.Sleep(time.Second)
        }

        log.Info("Attempting to connect to NATS")
        natsConnection, err = options.Connect()
        if err == nil {
            break
        }

        log.Errorf("NATS connection failed [%v]", err)
    }

    return natsConnection, err
}

Versions of nats-server and affected client libraries used:

Server nats-server 2.8.4 Windows

Client github.com/nats-io/nats.go v1.13.1-0.20220308171302-2f2f6968e98d

OS/Container environment:

Windows 10 Professional

Steps or code to reproduce the issue:

  1. Compile go app.
  2. Start server: ./nats-server -c .\leaf.conf
  3. Run client go app

Expected result:

No crash

Actual result:

Observed nats-server crash, but message was placed into stream before crash happened

[36192] 2022/08/24 12:38:42.783120 [DBG] 127.0.0.1:8256 - cid:10 - Client connection created
[36192] 2022/08/24 12:38:42.784476 [TRC] 127.0.0.1:8256 - cid:10 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"leaf_user","pass":"[REDACTED]","tls_required":false,"name":"Backend Service User Connection","lang":"go","version":"1.13.0","protocol":1,"echo":true,"headers":true,"no_responders":true}]
[36192] 2022/08/24 12:38:42.784476 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- [PING]
[36192] 2022/08/24 12:38:42.785050 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - ->> [PONG]
[36192] 2022/08/24 12:38:42.785600 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- [SUB _INBOX.yKc35aR2udok6P7A6u1pP5.*  1]
[36192] 2022/08/24 12:38:42.785600 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- [PUB JS.leaf_ingress@leaf.API.STREAM.INFO.time-stream _INBOX.yKc35aR2udok6P7A6u1pP5.ulePjr3L 0]
[36192] 2022/08/24 12:38:42.785600 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- MSG_PAYLOAD: [""]
[36192] 2022/08/24 12:38:42.786680 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - ->> [MSG _INBOX.yKc35aR2udok6P7A6u1pP5.ulePjr3L 1 640]
[36192] 2022/08/24 12:38:42.786680 [TRC] ACCOUNT - <<- [PUB $JS.EVENT.ADVISORY.API  1051]
[36192] 2022/08/24 12:38:42.786680 [TRC] ACCOUNT - <<- MSG_PAYLOAD: ["{\"type\":\"io.nats.jetstream.advisory.v1.api_audit\",\"id\":\"p9CcppauwI7vkUyCpLZWWo\",\"timestamp\":\"2022-08-24T16:38:42.7866466Z\",\"server\":\"leaf-server\",\"client\":{\"acc\":\"LEAF_USER\",\"svc\":\"LEAF_INGRESS\",\"rtt\":1355800,\"server\":\"leaf-server\",\"cluster\":\"leaf-server\"},\"subject\":\"$JS.API.STREAM.INFO.time-stream\",\"response\":\"{\\\"type\\\":\\\"io.nats.jetstream.api.v1.stream_info_response\\\",\\\"config\\\":{\\\"name\\\":\\\"time-stream\\\",\\\"subjects\\\":[\\\"time-stream\\\"],\\\"retention\\\":\\\"limits\\\",\\\"max_consumers\\\":-1,\\\"max_msgs\\\":-1,\\\"max_bytes\\\":-1,\\\"max_age\\\":0,\\\"max_msgs_per_subject\\\":-1,\\\"max_msg_size\\\":-1,\\\"discard\\\":\\\"old\\\",\\\"storage\\\":\\\"file\\\",\\\"num_replicas\\\":1,\\\"duplicate_window\\\":120000000000,\\\"sealed\\\":false,\\\"deny_delete\\\":false,\\\"deny_purge\\\":false,\\\"allow_rollup_hdrs\\\":false},\\\"created\\\":\\\"2022-08-24T14:57:06.5118754Z\\\",\\\"state\\\":{\\\"messages\\\":9,\\\"bytes\\\":612,\\\"first_seq\\\":1,\\\"first_ts\\\":\\\"2022-08-24T14:57:11.5195017Z\\\",\\\"last_seq\\\":9,\\\"last_ts\\\":\\\"2022-08-24T15:08:31.6928406Z\\\",\\\"num_subjects\\\":1,\\\"consumer_count\\\":0},\\\"domain\\\":\\\"leaf\\\"}\",\"domain\":\"leaf\"}"]
[36192] 2022/08/24 12:38:42.788278 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- [PUB time-stream _INBOX.yKc35aR2udok6P7A6u1pP5.osGTP9X9 27]
[36192] 2022/08/24 12:38:42.788379 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- MSG_PAYLOAD: ["\"2022-08-24T12:38:42-04:00\""]
[36192] 2022/08/24 12:38:43.560338 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[36192] 2022/08/24 12:38:44.563297 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 5): dial tcp 0.0.0.0:34333: i/o timeout
[36192] 2022/08/24 12:38:44.878332 [DBG] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - Client Ping Timer
[36192] 2022/08/24 12:38:44.878332 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - ->> [PING]
[36192] 2022/08/24 12:38:44.879184 [TRC] 127.0.0.1:8256 - cid:10 - "v1.13.0:go:Backend Service User Connection" - <<- [PONG]
runtime: goroutine stack exceeds 1000000000-byte limit
runtime: sp=0xc0205813b0 stack=[0xc020580000, 0xc040580000]
fatal error: stack overflow

runtime stack:
runtime.throw({0xacf21a, 0xed96e0})
        /home/travis/.gimme/versions/go1.17.10.linux.amd64/src/runtime/panic.go:1198 +0x76
runtime.newstack()
        /home/travis/.gimme/versions/go1.17.10.linux.amd64/src/runtime/stack.go:1088 +0x5cc
runtime.morestack()
        /home/travis/.gimme/versions/go1.17.10.linux.amd64/src/runtime/asm_amd64.s:461 +0x93

goroutine 37 [running]:
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc000087980, 0xc000422e10, 0xc000125b00, {0xc009cd9760, 0x7e, 0xa8})
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/client.go:3830 +0x113e fp=0xc0205813c0 sp=0xc0205813b8 pc=0x7f251e
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse(0xc000125b00, 0xc020581470, 0x4d1789, 0x11, {0xc009cbbf68, 0x0}, {0x0, 0x0}, {0xc009cd9760, 0x7e, ...})
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/accounts.go:2118 +0x131 fp=0xc020581418 sp=0xc0205813c0 pc=0x7c60b1
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse-fm(0x0, 0x0, 0x0, {0xc009cbbf68, 0x0}, {0x0, 0x0}, {0xc009cd9760, 0x7e, 0xa8})
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/accounts.go:2103 +0x77 fp=0xc020581480 sp=0xc020581418 pc=0x9c03b7
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc000087980, 0xc000183e00, 0x4, {0xc009cbbf50, 0x0, 0x18}, {0x0, 0x0, 0x0}, {0xc000088e00, ...}, ...)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/client.go:3173 +0xc4d fp=0xc0205816f8 sp=0xc020581480 pc=0x7edacd
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc000087980, 0x0, 0xc000226930, {0xc009cd9760, 0x7e, 0xa8}, {0xf83200, 0x0, 0x0}, {0xc009cbbf50, ...}, ...)
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/client.go:4168 +0xa76 fp=0xc020581c70 sp=0xc0205816f8 pc=0x7f34d6
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc000087980, 0xc00016e510, 0xc0001258c0, {0xc009cd96b0, 0x7e, 0xa8})
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/client.go:3984 +0xed1 fp=0xc020581f30 sp=0xc020581c70 pc=0x7f22b1
github.com/nats-io/nats-server/v2/server.(*Account).addServiceImportSub.func1(0x0, 0x0, 0x0, {0x0, 0x0}, {0x0, 0x0}, {0xc009cd96b0, 0x7e, 0xa8})
        /home/travis/gopath/src/github.com/nats-io/nats-server/server/accounts.go:1935 +0x32 fp=0xc020581f70 sp=0xc020581f30 pc=0x7c4d32
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc000087980, 0xc000182180, 0x5, {0xc009cd7cb0, 0x0, 0x30}, {0x0, 0x0, 0x0}, {0xc000088e00, ...}, ...)
...
kozlovic commented 2 years ago

@apis Could you please try with the main of NATS Server (or at least after this PR was merged: https://github.com/nats-io/nats-server/pull/3393). If you run docker images, you could try with the nightly synadia/nats-server:nightly.

We believe this issue may have been fixed.

apis commented 2 years ago

@kozlovic I tested it with latest main (2.9.0-RC.8) it throws the same error:

PS C:\sandbox\Spikes\jetstream-bug\nats> ./nats-server2 -DV -c .\leaf.conf
[3788] 2022/08/24 13:04:57.451402 [INF] Starting nats-server
[3788] 2022/08/24 13:04:57.452709 [INF]   Version:  2.9.0-RC.8
[3788] 2022/08/24 13:04:57.452709 [INF]   Git:      [not set]
[3788] 2022/08/24 13:04:57.452709 [DBG]   Go build: go1.18.1
[3788] 2022/08/24 13:04:57.453431 [INF]   Cluster:  leaf-server
[3788] 2022/08/24 13:04:57.453431 [INF]   Name:     leaf-server
[3788] 2022/08/24 13:04:57.453431 [INF]   Node:     1nWZLJcM
[3788] 2022/08/24 13:04:57.453431 [INF]   ID:       NDKTKU6BJC4LPKGU77B2ASROLEDCRXL323CZDRPR5QBXLWIHRUPLK2FA
[3788] 2022/08/24 13:04:57.453431 [WRN] Plaintext passwords detected, use nkeys or bcrypt
[3788] 2022/08/24 13:04:57.454016 [INF] Using configuration file: .\leaf.conf
[3788] 2022/08/24 13:04:57.454563 [INF] Starting JetStream
[3788] 2022/08/24 13:04:57.455093 [DBG] JetStream creating dynamic configuration - 47.92 GB memory, 1.00 TB disk
[3788] 2022/08/24 13:04:57.456418 [INF]     _ ___ _____ ___ _____ ___ ___   _   __  __
[3788] 2022/08/24 13:04:57.456926 [INF]  _ | | __|_   _/ __|_   _| _ \ __| /_\ |  \/  |
[3788] 2022/08/24 13:04:57.456990 [INF] | || | _|  | | \__ \ | | |   / _| / _ \| |\/| |
[3788] 2022/08/24 13:04:57.456990 [INF]  \__/|___| |_| |___/ |_| |_|_\___/_/ \_\_|  |_|
[3788] 2022/08/24 13:04:57.457652 [INF]
[3788] 2022/08/24 13:04:57.457740 [INF]          https://docs.nats.io/jetstream
[3788] 2022/08/24 13:04:57.457740 [INF]
[3788] 2022/08/24 13:04:57.458257 [INF] ---------------- JETSTREAM ----------------
[3788] 2022/08/24 13:04:57.458400 [INF]   Max Memory:      47.92 GB
[3788] 2022/08/24 13:04:57.458669 [INF]   Max Storage:     1.00 TB
[3788] 2022/08/24 13:04:57.458766 [INF]   Store Directory: "store_leaf\jetstream"
[3788] 2022/08/24 13:04:57.458766 [INF]   Domain:          leaf
[3788] 2022/08/24 13:04:57.459290 [INF] -------------------------------------------
[3788] 2022/08/24 13:04:57.459477 [DBG]   Exports:
[3788] 2022/08/24 13:04:57.459477 [DBG]      $JS.API.>
[3788] 2022/08/24 13:04:57.460100 [DBG] Enabled JetStream for account "LEAF_INGRESS"
[3788] 2022/08/24 13:04:57.460100 [DBG]   Max Memory:      -1 B
[3788] 2022/08/24 13:04:57.460607 [DBG]   Max Storage:     -1 B
[3788] 2022/08/24 13:04:57.462701 [DBG] JetStream state for account "LEAF_INGRESS" recovered
[3788] 2022/08/24 13:04:57.462868 [DBG] Enabled JetStream for account "HUB_USER"
[3788] 2022/08/24 13:04:57.462868 [DBG]   Max Memory:      -1 B
[3788] 2022/08/24 13:04:57.463373 [DBG]   Max Storage:     -1 B
[3788] 2022/08/24 13:04:57.465017 [DBG] JetStream state for account "HUB_USER" recovered
[3788] 2022/08/24 13:04:57.465017 [DBG] Enabled JetStream for account "LEAF_USER"
[3788] 2022/08/24 13:04:57.465017 [DBG]   Max Memory:      -1 B
[3788] 2022/08/24 13:04:57.465595 [DBG]   Max Storage:     -1 B
[3788] 2022/08/24 13:04:57.467125 [DBG] JetStream state for account "LEAF_USER" recovered
[3788] 2022/08/24 13:04:57.469893 [INF] Listening for client connections on 0.0.0.0:34111
[3788] 2022/08/24 13:04:57.469893 [DBG] Get non local IPs for "0.0.0.0"
[3788] 2022/08/24 13:04:57.512561 [DBG]   ip=172.28.112.1
[3788] 2022/08/24 13:04:57.550545 [DBG]   ip=fd5e:9a9e:c5bd:10:7d3a:5371:a3e0:ce8e
[3788] 2022/08/24 13:04:57.551554 [DBG]   ip=fd5e:9a9e:c5bd:10:8c0:8d5d:bce6:90be
[3788] 2022/08/24 13:04:57.551799 [DBG]   ip=fd5e:9a9e:c5bd:10:15af:9cd6:b21c:e8e0
[3788] 2022/08/24 13:04:57.551799 [DBG]   ip=fd5e:9a9e:c5bd:10:d431:eca6:6145:dd68
[3788] 2022/08/24 13:04:57.551799 [DBG]   ip=192.168.1.190
[3788] 2022/08/24 13:04:57.588571 [DBG]   ip=172.31.144.1
[3788] 2022/08/24 13:04:57.601570 [DBG]   ip=172.25.0.1
[3788] 2022/08/24 13:04:57.601829 [INF] Server is ready
[3788] 2022/08/24 13:04:57.601829 [DBG] maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined
[3788] 2022/08/24 13:04:57.601829 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:04:58.615822 [ERR] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 1): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:04:59.620309 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:00.620550 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 2): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:01.625179 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:02.638929 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 3): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:03.651219 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:04.659132 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 4): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:05.660444 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:06.667061 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 5): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:07.682098 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:08.685821 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 6): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:09.686363 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:10.687349 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 7): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:11.689782 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:12.693568 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 8): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:13.704502 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:14.705996 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 9): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:15.720178 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:16.724301 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 10): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:17.730905 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:18.741737 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 11): dial tcp 0.0.0.0:34333: i/o timeout
[3788] 2022/08/24 13:05:19.567767 [DBG] 127.0.0.1:9310 - cid:7 - Client connection created
[3788] 2022/08/24 13:05:19.568788 [TRC] 127.0.0.1:9310 - cid:7 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"leaf_user","pass":"[REDACTED]","tls_required":false,"name":"Backend Service User Connection","lang":"go","version":"1.13.0","protocol":1,"echo":true,"headers":true,"no_responders":true}]
[3788] 2022/08/24 13:05:19.569388 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- [PING]
[3788] 2022/08/24 13:05:19.569388 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - ->> [PONG]
[3788] 2022/08/24 13:05:19.569970 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- [SUB _INBOX.XBxlvlrp7r0R5RN49P6IzL.*  1]
[3788] 2022/08/24 13:05:19.569970 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- [PUB JS.leaf_ingress@leaf.API.STREAM.INFO.time-stream _INBOX.XBxlvlrp7r0R5RN49P6IzL.jH2bwuPl 0]
[3788] 2022/08/24 13:05:19.570550 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- MSG_PAYLOAD: [""]
[3788] 2022/08/24 13:05:19.571252 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - ->> [MSG _INBOX.XBxlvlrp7r0R5RN49P6IzL.jH2bwuPl 1 127]
[3788] 2022/08/24 13:05:19.571252 [TRC] ACCOUNT - <<- [PUB $JS.EVENT.ADVISORY.API  472]
[3788] 2022/08/24 13:05:19.571757 [TRC] ACCOUNT - <<- MSG_PAYLOAD: ["{\"type\":\"io.nats.jetstream.advisory.v1.api_audit\",\"id\":\"V8Mg5G9V4UMnUSwufprHw4\",\"timestamp\":\"2022-08-24T17:05:19.5712522Z\",\"server\":\"leaf-server\",\"client\":{\"acc\":\"LEAF_USER\",\"svc\":\"LEAF_INGRESS\",\"rtt\":1686000,\"server\":\"leaf-server\",\"cluster\":\"leaf-server\"},\"subject\":\"$JS.API.STREAM.INFO.time-stream\",\"response\":\"{\\\"type\\\":\\\"io.nats.jetstream.api.v1.stream_info_response\\\",\\\"error\\\":{\\\"code\\\":404,\\\"err_code\\\":10059,\\\"description\\\":\\\"stream not found\\\"}}\",\"domain\":\"leaf\"}"]
[3788] 2022/08/24 13:05:19.572339 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- [PUB JS.leaf_ingress@leaf.API.STREAM.CREATE.time-stream _INBOX.XBxlvlrp7r0R5RN49P6IzL.tEo3sh51 202]
[3788] 2022/08/24 13:05:19.572339 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- MSG_PAYLOAD: ["{\"name\":\"time-stream\",\"subjects\":[\"time-stream\"],\"retention\":\"limits\",\"max_consumers\":0,\"max_msgs\":0,\"max_bytes\":0,\"discard\":\"old\",\"max_age\":0,\"max_msgs_per_subject\":0,\"storage\":\"file\",\"num_replicas\":0}"]
[3788] 2022/08/24 13:05:19.578301 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - ->> [MSG _INBOX.XBxlvlrp7r0R5RN49P6IzL.tEo3sh51 1 609]
[3788] 2022/08/24 13:05:19.578301 [TRC] ACCOUNT - <<- [PUB $JS.EVENT.ADVISORY.API  1265]
[3788] 2022/08/24 13:05:19.578827 [TRC] ACCOUNT - <<- MSG_PAYLOAD: ["{\"type\":\"io.nats.jetstream.advisory.v1.api_audit\",\"id\":\"V8Mg5G9V4UMnUSwufprI06\",\"timestamp\":\"2022-08-24T17:05:19.5783019Z\",\"server\":\"leaf-server\",\"client\":{\"acc\":\"LEAF_USER\",\"svc\":\"LEAF_INGRESS\",\"rtt\":1686000,\"server\":\"leaf-server\",\"cluster\":\"leaf-server\"},\"subject\":\"$JS.API.STREAM.CREATE.time-stream\",\"request\":\"{\\\"name\\\":\\\"time-stream\\\",\\\"subjects\\\":[\\\"time-stream\\\"],\\\"retention\\\":\\\"limits\\\",\\\"max_consumers\\\":0,\\\"max_msgs\\\":0,\\\"max_bytes\\\":0,\\\"discard\\\":\\\"old\\\",\\\"max_age\\\":0,\\\"max_msgs_per_subject\\\":0,\\\"storage\\\":\\\"file\\\",\\\"num_replicas\\\":0}\",\"response\":\"{\\\"type\\\":\\\"io.nats.jetstream.api.v1.stream_create_response\\\",\\\"config\\\":{\\\"name\\\":\\\"time-stream\\\",\\\"subjects\\\":[\\\"time-stream\\\"],\\\"retention\\\":\\\"limits\\\",\\\"max_consumers\\\":-1,\\\"max_msgs\\\":-1,\\\"max_bytes\\\":-1,\\\"max_age\\\":0,\\\"max_msgs_per_subject\\\":-1,\\\"max_msg_size\\\":-1,\\\"discard\\\":\\\"old\\\",\\\"storage\\\":\\\"file\\\",\\\"num_replicas\\\":1,\\\"duplicate_window\\\":120000000000,\\\"sealed\\\":false,\\\"deny_delete\\\":false,\\\"deny_purge\\\":false,\\\"allow_rollup_hdrs\\\":false},\\\"created\\\":\\\"2022-08-24T17:05:19.5729039Z\\\",\\\"state\\\":{\\\"messages\\\":0,\\\"bytes\\\":0,\\\"first_seq\\\":0,\\\"first_ts\\\":\\\"0001-01-01T00:00:00Z\\\",\\\"last_seq\\\":0,\\\"last_ts\\\":\\\"0001-01-01T00:00:00Z\\\",\\\"consumer_count\\\":0},\\\"did_create\\\":true}\",\"domain\":\"leaf\"}"]
[3788] 2022/08/24 13:05:19.579426 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- [PUB time-stream _INBOX.XBxlvlrp7r0R5RN49P6IzL.dbYqMv31 27]
[3788] 2022/08/24 13:05:19.579426 [TRC] 127.0.0.1:9310 - cid:7 - "v1.13.0:go:Backend Service User Connection" - <<- MSG_PAYLOAD: ["\"2022-08-24T13:05:19-04:00\""]
[3788] 2022/08/24 13:05:19.742894 [DBG] Trying to connect as leafnode to remote server on "0.0.0.0:34333"
[3788] 2022/08/24 13:05:20.754748 [DBG] Error trying to connect as leafnode to remote server "0.0.0.0:34333" (attempt 12): dial tcp 0.0.0.0:34333: i/o timeout
runtime: goroutine stack exceeds 1000000000-byte limit
runtime: sp=0xc0205815c0 stack=[0xc020580000, 0xc040580000]
fatal error: stack overflow

runtime stack:
runtime.throw({0x84ace3?, 0xc40d80?})
        c:/sandbox/go/src/runtime/panic.go:992 +0x76
runtime.newstack()
        c:/sandbox/go/src/runtime/stack.go:1101 +0x5db
runtime.morestack()
        c:/sandbox/go/src/runtime/asm_amd64.s:547 +0x93

goroutine 40 [running]:
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc00006b300, 0xc0005bc000, 0xc0000e9b00, {0xc00bebcbb0, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:3853 +0x11fe fp=0xc0205815d0 sp=0xc0205815c8 pc=0x55317e
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse(0xc0000e9b00, 0xc020581698?, 0xc00006b300, 0x11?, {0xc00beb0d80?, 0x0?}, {0x0?, 0x0?}, {0xc00bebcbb0, 0x7d, ...})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/accounts.go:2151 +0x1fb fp=0xc020581640 sp=0xc0205815d0 pc=0x5205bb
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse-fm(0x0?, 0x0?, 0x0?, {0xc00beb0d80?, 0x0?}, {0x0?, 0x0?}, {0xc00bebcbb0, 0x7d, 0xa8})
        <autogenerated>:1 +0x77 fp=0xc0205816a8 sp=0xc020581640 pc=0x73e0d7
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc00006b300, 0xc00014ea80, 0xc0000e9b00, {0xc00beb0d68, 0x11, 0x18}, {0x0, 0x0, 0x0}, {0xc00006c798, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:3192 +0xbed fp=0xc0205818e0 sp=0xc0205816a8 pc=0x54e6cd
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc00006b300, 0x0?, 0xc000282c00, {0xc00bebcbb0, 0x7d, 0xa8}, {0xcd5340, 0x0, 0x0?}, {0xc00beb0d68, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4200 +0xa76 fp=0xc020581e60 sp=0xc0205818e0 pc=0x554136
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc00006b300, 0xc000134480, 0xc0000e98c0, {0xc00bebcb00, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4016 +0xf91 fp=0xc020582148 sp=0xc020581e60 pc=0x552f11
github.com/nats-io/nats-server/v2/server.(*Account).addServiceImportSub.func1(0x0?, 0x0?, 0x0?, {0x0?, 0x0?}, {0x0?, 0x0?}, {0xc00bebcb00, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/accounts.go:1962 +0x32 fp=0xc020582188 sp=0xc020582148 pc=0x51f292
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc00006b300, 0xc00014e180, 0xc0000e98c0, {0xc00beb5500, 0x26, 0x30}, {0x0, 0x0, 0x0}, {0xc00006c798, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:3192 +0xbed fp=0xc0205823c0 sp=0xc020582188 pc=0x54e6cd
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc00006b300, 0x0?, 0xc000282c30, {0xc00bebcb00, 0x7d, 0xa8}, {0xcd5340, 0x0, 0x0?}, {0xc00beb5500, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4200 +0xa76 fp=0xc020582940 sp=0xc0205823c0 pc=0x554136
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc00006b300, 0xc0005bc000, 0xc0000e9b00, {0xc00bebcb00, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4016 +0xf91 fp=0xc020582c28 sp=0xc020582940 pc=0x552f11
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse(0xc0000e9b00, 0xc020582cf0?, 0xc00006b300, 0x11?, {0xc00beb0d20?, 0x0?}, {0x0?, 0x0?}, {0xc00bebcb00, 0x7d, ...})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/accounts.go:2151 +0x1fb fp=0xc020582c98 sp=0xc020582c28 pc=0x5205bb
github.com/nats-io/nats-server/v2/server.(*Account).processServiceImportResponse-fm(0x0?, 0x0?, 0x0?, {0xc00beb0d20?, 0x0?}, {0x0?, 0x0?}, {0xc00bebcb00, 0x7d, 0xa8})
        <autogenerated>:1 +0x77 fp=0xc020582d00 sp=0xc020582c98 pc=0x73e0d7
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc00006b300, 0xc00014ea80, 0xc0000e9b00, {0xc00beb0d08, 0x11, 0x18}, {0x0, 0x0, 0x0}, {0xc00006c798, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:3192 +0xbed fp=0xc020582f38 sp=0xc020582d00 pc=0x54e6cd
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc00006b300, 0x0?, 0xc000282c00, {0xc00bebcb00, 0x7d, 0xa8}, {0xcd5340, 0x0, 0x0?}, {0xc00beb0d08, ...}, ...)
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4200 +0xa76 fp=0xc0205834b8 sp=0xc020582f38 pc=0x554136
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc00006b300, 0xc000134480, 0xc0000e98c0, {0xc00bebca50, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/client.go:4016 +0xf91 fp=0xc0205837a0 sp=0xc0205834b8 pc=0x552f11
github.com/nats-io/nats-server/v2/server.(*Account).addServiceImportSub.func1(0x0?, 0x0?, 0x0?, {0x0?, 0x0?}, {0x0?, 0x0?}, {0xc00bebca50, 0x7d, 0xa8})
        C:/sandbox/Spikes/jetstream-bug/nats-server/server/accounts.go:1962 +0x32 fp=0xc0205837e0 sp=0xc0205837a0 pc=0x51f292
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc00006b300, 0xc00014e180, 0xc0000e98c0, {0xc00beb5440, 0x26, 0x30}, {0x0, 0x0, 0x0}, {0xc00006c798, ...}, ...)
kozlovic commented 2 years ago

Ok, thank you for the report and config/steps to reproduce!

kozlovic commented 2 years ago

@apis Still looking at a solution, but to unblock you, note that if you remove the "_INBOX.>" imports/exports from your configuration, you will not get the stack overflow without preventing communication from happening. Will keep you posted on a resolution on preventing the cycle.