search

nats-io / jetstream

JetStream Utilities
Apache License 2.0
455 stars 44 forks source link

jetstream consumes 100% cpu and becomes un responsive #143

Closed matthiashanel closed 4 years ago

matthiashanel commented 4 years ago

Server consumes 100% cpu and becomes un responsive. (below are two different dumps of go routines) Version used trunk. I was investigating an issue when creating a consumer using StartWithLastReceived. I will continue investigating my original issue and update this one if it turns out they are related. Filing the issue now so it's not lost...

I am using jsm to create a stream and a consumer. Consumer creating fails for a reason that I'm currently investigating But basically it fails whenever I use 

Connect: faas-cluster to nats://localhost:4222
Subscribing to: faas-cluster/faas/faas-request at nats://localhost:4222
Error creating consumer faas on nats://localhost:4222: consumer starting position conflict
panic: Error creating consumer faas on nats://localhost:4222: consumer starting position conflict

The code involved works fine when using jsm.DeliverAllAvailable instead of jsm.StartWithLastReceived. As soon as I use jsm.StartWithLastReceived() it fails with the above issue.

    stream, err := jsm.LoadOrNewStream(
        q.clusterID,
        jsm.Subjects(q.clusterID+".>"),
        jsm.MemoryStorage(),
        jsm.MaxBytes(1*1024*1024),
        jsm.LimitsRetention(),
    )
...
    opts := []jsm.ConsumerOption{
        jsm.StartWithLastReceived(),
        jsm.AckWait(q.ackWait),
        jsm.AcknowledgeExplicit(),
        jsm.FilterStreamBySubject(q.clusterID+"."+q.subject),
    }
    if q.durable != "" {
        opts = append(opts, jsm.DurableName(q.durable))
    }

When I then played around creating the consumer manually using nats the tool times out.

./nats -s 0.0.0.0:4222 consumer add faas-cluster TEST --pull --deliver last --filter faas-cluster.faas-reques --max-deliver=-1
nats: error: Consumer creation failed: nats: timeout

Cpu goes up to 100%

Processes: 647 total, 4 running, 643 sleeping, 4191 threads                                                                                                                                                                                                            15:33:13
Load Avg: 3.42, 3.54, 3.30  CPU usage: 10.75% user, 4.1% sys, 85.22% idle   SharedLibs: 483M resident, 75M data, 51M linkedit. MemRegions: 613025 total, 15G resident, 201M private, 7838M shared. PhysMem: 48G used (6787M wired), 16G unused.
VM: 4494G vsize, 1879M framework vsize, 125577881(0) swapins, 130489638(0) swapouts. Networks: packets: 134618199/133G in, 165927956/128G out. Disks: 12699283/700G read, 28240367/920G written.

PID    COMMAND      %CPU  TIME     #TH  #WQ  #POR MEM   PURG CMPR PGRP  PPID STATE   BOOSTS    %CPU_ME %CPU_OTHRS UID  FAUL COW  MSGS MSGR SYSBSD SYSM CSW    PAGE IDLE POWER INSTRS     CYCLES     USER          #MRE RPRV VPRV VSIZ KPRV KSHR
13034  nats-server  99.8  05:20.68 10/1 0    36   4112K 0B   0B   13034 592  running *0[1]     0.00000 0.00000    501  4560 737  71   27   59097+ 138  97540+ 0    0    99.8  5959340410 3132506637 matthiashanel N/A  N/A  N/A  N/A  N/A  N/A

ctrl c seems to not work anymore either. Below are two traces: first one with ctrl+\ to dump the stacks The second one I do ctrl+c before ctrl+\, there the stack seems a little more interesting. (waiting for a lock?)

 rm -rf test ; ./nats-server -js -DVV  -sd ./test
[13034] 2020/04/08 15:27:45.437728 [INF] Starting nats-server version 2.2.0-beta.7
[13034] 2020/04/08 15:27:45.437812 [DBG] Go build version go1.14.1
[13034] 2020/04/08 15:27:45.437815 [INF] Git commit [not set]
[13034] 2020/04/08 15:27:45.437825 [INF] Starting JetStream
[13034] 2020/04/08 15:27:45.437838 [DBG] JetStream creating dynamic configuration - 75% of system memory, 1.00 TB disk
[13034] 2020/04/08 15:27:45.438066 [DBG] Created system account: "$SYS"
[13034] 2020/04/08 15:27:45.438148 [TRC] SYSTEM - <<- [SUB $SYS._INBOX.WWMR0d.* 2]
[13034] 2020/04/08 15:27:45.438175 [TRC] SYSTEM - <<- [SUB $SYS.SERVER.ACCOUNT.*.CONNS 3]
[13034] 2020/04/08 15:27:45.438188 [TRC] SYSTEM - <<- [SUB $SYS._INBOX_.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP 4]
[13034] 2020/04/08 15:27:45.438193 [TRC] SYSTEM - <<- [SUB $SYS.REQ.ACCOUNT.*.CONNS 5]
[13034] 2020/04/08 15:27:45.438198 [TRC] SYSTEM - <<- [SUB $SYS.REQ.ACCOUNT.NSUBS 6]
[13034] 2020/04/08 15:27:45.438201 [TRC] SYSTEM - <<- [SUB $SYS.SERVER.*.SHUTDOWN 7]
[13034] 2020/04/08 15:27:45.438205 [TRC] SYSTEM - <<- [SUB $SYS.ACCOUNT.*.CLAIMS.UPDATE 8]
[13034] 2020/04/08 15:27:45.438212 [TRC] SYSTEM - <<- [SUB $SYS.REQ.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ 9]
[13034] 2020/04/08 15:27:45.438219 [TRC] SYSTEM - <<- [SUB $SYS.REQ.SERVER.PING 10]
[13034] 2020/04/08 15:27:45.438227 [TRC] SYSTEM - <<- [SUB $SYS.ACCOUNT.*.LEAFNODE.CONNECT 11]
[13034] 2020/04/08 15:27:45.438232 [TRC] SYSTEM - <<- [SUB $SYS.LATENCY.M2.WWMR0d 12]
[13034] 2020/04/08 15:27:45.438239 [TRC] SYSTEM - <<- [SUB $SYS.DEBUG.SUBSCRIBERS 13]
[13034] 2020/04/08 15:27:45.438259 [TRC] SYSTEM - <<- [SUB $JS.ENABLED 14]
[13034] 2020/04/08 15:27:45.438266 [TRC] SYSTEM - <<- [SUB $JS.INFO 15]
[13034] 2020/04/08 15:27:45.438272 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.CREATE 16]
[13034] 2020/04/08 15:27:45.438276 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.LIST 17]
[13034] 2020/04/08 15:27:45.438279 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.INFO 18]
[13034] 2020/04/08 15:27:45.438283 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.DELETE 19]
[13034] 2020/04/08 15:27:45.438286 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CREATE 20]
[13034] 2020/04/08 15:27:45.438290 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.UPDATE 21]
[13034] 2020/04/08 15:27:45.438294 [TRC] SYSTEM - <<- [SUB $JS.STREAM.LIST 22]
[13034] 2020/04/08 15:27:45.438297 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.INFO 23]
[13034] 2020/04/08 15:27:45.438301 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.DELETE 24]
[13034] 2020/04/08 15:27:45.438304 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.PURGE 25]
[13034] 2020/04/08 15:27:45.438308 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.MSG.DELETE 26]
[13034] 2020/04/08 15:27:45.438314 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.CREATE 27]
[13034] 2020/04/08 15:27:45.444681 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.EPHEMERAL.CONSUMER.CREATE 28]
[13034] 2020/04/08 15:27:45.438386 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.ACCOUNT.$SYS.CONNS  366]
[13034] 2020/04/08 15:27:45.444695 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMERS 29]
[13034] 2020/04/08 15:27:45.444707 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.INFO 30]
[13034] 2020/04/08 15:27:45.444712 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.DELETE 31]
[13034] 2020/04/08 15:27:45.444719 [INF] ----------- JETSTREAM (Beta) -----------
[13034] 2020/04/08 15:27:45.444725 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 2,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:27:45.438145-04:00\"\n  },\n  \"acc\": \"$SYS\",\n  \"conns\": 0,\n  \"leafnodes\": 0,\n  \"total_conns\": 0\n}"]
[13034] 2020/04/08 15:27:45.444726 [INF]   Max Memory:      48.00 GB
[13034] 2020/04/08 15:27:45.444758 [INF]   Max Storage:     1.00 TB
[13034] 2020/04/08 15:27:45.444760 [INF]   Store Directory: "test/jetstream"
[13034] 2020/04/08 15:27:45.444765 [DBG]   Exports:
[13034] 2020/04/08 15:27:45.444766 [DBG]      $JS.ENABLED
[13034] 2020/04/08 15:27:45.444768 [DBG]      $JS.INFO
[13034] 2020/04/08 15:27:45.444770 [DBG]      $JS.TEMPLATE.*.CREATE
[13034] 2020/04/08 15:27:45.444772 [DBG]      $JS.TEMPLATE.LIST
[13034] 2020/04/08 15:27:45.445121 [DBG]      $JS.TEMPLATE.*.INFO
[13034] 2020/04/08 15:27:45.445125 [DBG]      $JS.TEMPLATE.*.DELETE
[13034] 2020/04/08 15:27:45.445127 [DBG]      $JS.STREAM.*.CREATE
[13034] 2020/04/08 15:27:45.445129 [DBG]      $JS.STREAM.*.UPDATE
[13034] 2020/04/08 15:27:45.445132 [DBG]      $JS.STREAM.LIST
[13034] 2020/04/08 15:27:45.445133 [DBG]      $JS.STREAM.*.INFO
[13034] 2020/04/08 15:27:45.445135 [DBG]      $JS.STREAM.*.DELETE
[13034] 2020/04/08 15:27:45.445137 [DBG]      $JS.STREAM.*.PURGE
[13034] 2020/04/08 15:27:45.445138 [DBG]      $JS.STREAM.*.MSG.DELETE
[13034] 2020/04/08 15:27:45.445141 [DBG]      $JS.STREAM.*.CONSUMER.*.CREATE
[13034] 2020/04/08 15:27:45.445142 [DBG]      $JS.STREAM.*.EPHEMERAL.CONSUMER.CREATE
[13034] 2020/04/08 15:27:45.445144 [DBG]      $JS.STREAM.*.CONSUMERS
[13034] 2020/04/08 15:27:45.445146 [DBG]      $JS.STREAM.*.CONSUMER.*.INFO
[13034] 2020/04/08 15:27:45.450960 [DBG]      $JS.STREAM.*.CONSUMER.*.DELETE
[13034] 2020/04/08 15:27:45.450969 [INF] ----------------------------------------
[13034] 2020/04/08 15:27:45.451066 [DBG] Enabled JetStream for account "$G"
[13034] 2020/04/08 15:27:45.451074 [DBG]   Max Memory:      48.00 GB
[13034] 2020/04/08 15:27:45.451076 [DBG]   Max Storage:     1.00 TB
[13034] 2020/04/08 15:27:45.451110 [INF]   Upgrading storage directory structure for "$G"
[13034] 2020/04/08 15:27:45.451278 [INF]   Recovering JetStream state for account "$G"
[13034] 2020/04/08 15:27:45.451375 [INF] JetStream state for account "$G" recovered
[13034] 2020/04/08 15:27:45.451578 [INF] Listening for client connections on 0.0.0.0:4222
[13034] 2020/04/08 15:27:45.451582 [INF] Server id is NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP
[13034] 2020/04/08 15:27:45.451584 [INF] Server is ready
[13034] 2020/04/08 15:27:45.451588 [DBG] Get non local IPs for "0.0.0.0"
[13034] 2020/04/08 15:27:45.451780 [DBG]   ip=2604:2000:1201:a4ca:c01:aab0:cbd4:cdee
[13034] 2020/04/08 15:27:45.451783 [DBG]   ip=2604:2000:1201:a4ca:ccd:e38c:b660:51eb
[13034] 2020/04/08 15:27:45.451785 [DBG]   ip=2604:2000:1201:a4ca::3fb
[13034] 2020/04/08 15:27:45.451787 [DBG]   ip=192.168.1.111
[13034] 2020/04/08 15:27:45.451789 [DBG]   ip=2604:2000:1201:a4ca:98a:277c:af08:fc99
[13034] 2020/04/08 15:27:45.451792 [DBG]   ip=2604:2000:1201:a4ca:8909:e45e:1d2e:1f03
[13034] 2020/04/08 15:27:45.454751 [DBG]   ip=2604:2000:1201:a4ca:4144:f953:6c7b:4d4
[13034] 2020/04/08 15:27:45.454757 [DBG]   ip=2604:2000:1201:a4ca:e4ac:2fe5:737f:f213
[13034] 2020/04/08 15:27:45.454901 [DBG]   ip=192.168.64.1
[13034] 2020/04/08 15:27:45.454907 [DBG]   ip=fd8a:db99:b964:cc77:14f0:15d0:3624:cc8e
[13034] 2020/04/08 15:27:45.454909 [DBG]   ip=fd8a:db99:b964:cc77:6163:e37f:e697:263
[13034] 2020/04/08 15:27:45.454911 [DBG]   ip=fd8a:db99:b964:cc77:ec83:59b9:fd49:cfa5
[13034] 2020/04/08 15:27:45.454913 [DBG]   ip=fd8a:db99:b964:cc77:285b:585a:fa66:b3a9
[13034] 2020/04/08 15:27:45.454915 [DBG]   ip=fd8a:db99:b964:cc77:c0fb:dc20:efe5:a2a5
[13034] 2020/04/08 15:27:45.454917 [DBG]   ip=fd8a:db99:b964:cc77:3d36:1b5f:ba53:baa5
[13034] 2020/04/08 15:27:48.361664 [DBG] [::1]:55505 - cid:3 - Client connection created
[13034] 2020/04/08 15:27:48.362437 [TRC] [::1]:55505 - cid:3 - <<- [CONNECT {"verbose":false,"pedantic":false,"tls_required":false,"name":"faas-worker-MacBook-Pro_local","lang":"go","version":"1.9.2","protocol":1,"echo":true}]
[13034] 2020/04/08 15:27:48.362577 [TRC] [::1]:55505 - cid:3 - <<- [PING]
[13034] 2020/04/08 15:27:48.362582 [TRC] [::1]:55505 - cid:3 - ->> [PONG]
[13034] 2020/04/08 15:27:48.362889 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwtyR  1]
[13034] 2020/04/08 15:27:48.362946 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 1 1]
[13034] 2020/04/08 15:27:48.362976 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.ENABLED _INBOX.wvmQ7Wep77kx4INmQCwtyR 0]
[13034] 2020/04/08 15:27:48.362980 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: [""]
[13034] 2020/04/08 15:27:48.363164 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwtyR  3]
[13034] 2020/04/08 15:27:48.363173 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["+OK"]
[13034] 2020/04/08 15:27:48.363184 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '1'
[13034] 2020/04/08 15:27:48.363189 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwtyR 1  3]
[13034] 2020/04/08 15:27:48.363192 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 1]
[13034] 2020/04/08 15:27:48.363438 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwu17  2]
[13034] 2020/04/08 15:27:48.363442 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  436]
[13034] 2020/04/08 15:27:48.363467 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 2 1]
[13034] 2020/04/08 15:27:48.363503 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.INFO _INBOX.wvmQ7Wep77kx4INmQCwu17 0]
[13034] 2020/04/08 15:27:48.363507 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: [""]
[13034] 2020/04/08 15:27:48.363512 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydCqC\",\n  \"timestamp\": \"2020-04-08T19:27:48.363086Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.ENABLED\",\n  \"response\": \"+OK\"\n}"]
[13034] 2020/04/08 15:27:48.363595 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwu17  23]
[13034] 2020/04/08 15:27:48.363616 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'stream not found'"]
[13034] 2020/04/08 15:27:48.363623 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '2'
[13034] 2020/04/08 15:27:48.363654 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwu17 2  23]
[13034] 2020/04/08 15:27:48.363657 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 2]
[13034] 2020/04/08 15:27:48.363666 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  473]
[13034] 2020/04/08 15:27:48.363680 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydCt7\",\n  \"timestamp\": \"2020-04-08T19:27:48.363549Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.INFO\",\n  \"response\": \"-ERR 'stream not found'\"\n}"]
[13034] 2020/04/08 15:27:48.363970 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwu3n  3]
[13034] 2020/04/08 15:27:48.363982 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 3 1]
[13034] 2020/04/08 15:27:48.363986 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CREATE _INBOX.wvmQ7Wep77kx4INmQCwu3n 214]
[13034] 2020/04/08 15:27:48.364017 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: ["{\"name\":\"faas-cluster\",\"subjects\":[\"faas-cluster.\\u003e\"],\"retention\":\"limits\",\"max_consumers\":-1,\"max_msgs\":-1,\"max_bytes\":1048576,\"max_age\":31536000000000000,\"max_msg_size\":-1,\"storage\":\"memory\",\"num_replicas\":1}"]
[13034] 2020/04/08 15:27:48.364176 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwu3n  3]
[13034] 2020/04/08 15:27:48.364182 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["+OK"]
[13034] 2020/04/08 15:27:48.364188 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '3'
[13034] 2020/04/08 15:27:48.364191 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwu3n 3  3]
[13034] 2020/04/08 15:27:48.364194 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 3]
[13034] 2020/04/08 15:27:48.364201 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  715]
[13034] 2020/04/08 15:27:48.364216 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydCw2\",\n  \"timestamp\": \"2020-04-08T19:27:48.364142Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CREATE\",\n  \"request\": \"{\\\"name\\\":\\\"faas-cluster\\\",\\\"subjects\\\":[\\\"faas-cluster.\\\\u003e\\\"],\\\"retention\\\":\\\"limits\\\",\\\"max_consumers\\\":-1,\\\"max_msgs\\\":-1,\\\"max_bytes\\\":1048576,\\\"max_age\\\":31536000000000000,\\\"max_msg_size\\\":-1,\\\"storage\\\":\\\"memory\\\",\\\"num_replicas\\\":1}\",\n  \"response\": \"+OK\"\n}"]
[13034] 2020/04/08 15:27:48.364335 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwu6T  4]
[13034] 2020/04/08 15:27:48.364347 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 4 1]
[13034] 2020/04/08 15:27:48.364351 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.INFO _INBOX.wvmQ7Wep77kx4INmQCwu6T 0]
[13034] 2020/04/08 15:27:48.364354 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: [""]
[13034] 2020/04/08 15:27:48.364477 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwu6T  421]
[13034] 2020/04/08 15:27:48.364523 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"config\": {\n    \"name\": \"faas-cluster\",\n    \"subjects\": [\n      \"faas-cluster.\\u003e\"\n    ],\n    \"retention\": \"limits\",\n    \"max_consumers\": -1,\n    \"max_msgs\": -1,\n    \"max_bytes\": 1048576,\n    \"max_age\": 31536000000000000,\n    \"max_msg_size\": -1,\n    \"storage\": \"memory\",\n    \"num_replicas\": 1\n  },\n  \"state\": {\n    \"messages\": 0,\n    \"bytes\": 0,\n    \"first_seq\": 0,\n    \"last_seq\": 0,\n    \"consumer_count\": 0\n  }\n}"]
[13034] 2020/04/08 15:27:48.364529 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '4'
[13034] 2020/04/08 15:27:48.364549 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwu6T 4  421]
[13034] 2020/04/08 15:27:48.364551 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 4]
[13034] 2020/04/08 15:27:48.364560 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  936]
[13034] 2020/04/08 15:27:48.364583 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydCyx\",\n  \"timestamp\": \"2020-04-08T19:27:48.364433Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.INFO\",\n  \"response\": \"{\\n  \\\"config\\\": {\\n    \\\"name\\\": \\\"faas-cluster\\\",\\n    \\\"subjects\\\": [\\n      \\\"faas-cluster.\\\\u003e\\\"\\n    ],\\n    \\\"retention\\\": \\\"limits\\\",\\n    \\\"max_consumers\\\": -1,\\n    \\\"max_msgs\\\": -1,\\n    \\\"max_bytes\\\": 1048576,\\n    \\\"max_age\\\": 31536000000000000,\\n    \\\"max_msg_size\\\": -1,\\n    \\\"storage\\\": \\\"memory\\\",\\n    \\\"num_replicas\\\": 1\\n  },\\n  \\\"state\\\": {\\n    \\\"messages\\\": 0,\\n    \\\"bytes\\\": 0,\\n    \\\"first_seq\\\": 0,\\n    \\\"last_seq\\\": 0,\\n    \\\"consumer_count\\\": 0\\n  }\\n}\"\n}"]
[13034] 2020/04/08 15:27:48.364726 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwu99  5]
[13034] 2020/04/08 15:27:48.364735 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 5 1]
[13034] 2020/04/08 15:27:48.364742 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.faas.INFO _INBOX.wvmQ7Wep77kx4INmQCwu99 0]
[13034] 2020/04/08 15:27:48.364745 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: [""]
[13034] 2020/04/08 15:27:48.364786 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwu99  25]
[13034] 2020/04/08 15:27:48.364790 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'consumer not found'"]
[13034] 2020/04/08 15:27:48.364798 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '5'
[13034] 2020/04/08 15:27:48.364801 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwu99 5  25]
[13034] 2020/04/08 15:27:48.364803 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 5]
[13034] 2020/04/08 15:27:48.364814 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  489]
[13034] 2020/04/08 15:27:48.364823 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydD1s\",\n  \"timestamp\": \"2020-04-08T19:27:48.364765Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CONSUMER.faas.INFO\",\n  \"response\": \"-ERR 'consumer not found'\"\n}"]
[13034] 2020/04/08 15:27:48.364978 [TRC] [::1]:55505 - cid:3 - <<- [SUB _INBOX.wvmQ7Wep77kx4INmQCwuBp  6]
[13034] 2020/04/08 15:27:48.364989 [TRC] [::1]:55505 - cid:3 - <<- [UNSUB 6 1]
[13034] 2020/04/08 15:27:48.364999 [TRC] [::1]:55505 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.faas.CREATE _INBOX.wvmQ7Wep77kx4INmQCwuBp 278]
[13034] 2020/04/08 15:27:48.365010 [TRC] [::1]:55505 - cid:3 - <<- MSG_PAYLOAD: ["{\"stream_name\":\"faas-cluster\",\"config\":{\"delivery_subject\":\"\",\"durable_name\":\"faas\",\"start_time\":\"0001-01-01T00:00:00Z\",\"deliver_all\":true,\"deliver_last\":true,\"ack_policy\":\"explicit\",\"ack_wait\":30000000000,\"filter_subject\":\"faas-cluster.faas-request\",\"replay_policy\":\"instant\"}}"]
[13034] 2020/04/08 15:27:48.365155 [TRC] SYSTEM - <<- [PUB _INBOX.wvmQ7Wep77kx4INmQCwuBp  42]
[13034] 2020/04/08 15:27:48.365163 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'consumer starting position conflict'"]
[13034] 2020/04/08 15:27:48.365172 [DBG] [::1]:55505 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '6'
[13034] 2020/04/08 15:27:48.365176 [TRC] [::1]:55505 - cid:3 - ->> [MSG _INBOX.wvmQ7Wep77kx4INmQCwuBp 6  42]
[13034] 2020/04/08 15:27:48.365180 [TRC] [::1]:55505 - cid:3 - <-> [DELSUB 6]
[13034] 2020/04/08 15:27:48.365187 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  838]
[13034] 2020/04/08 15:27:48.365209 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydD4n\",\n  \"timestamp\": \"2020-04-08T19:27:48.36512Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55505,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CONSUMER.faas.CREATE\",\n  \"request\": \"{\\\"stream_name\\\":\\\"faas-cluster\\\",\\\"config\\\":{\\\"delivery_subject\\\":\\\"\\\",\\\"durable_name\\\":\\\"faas\\\",\\\"start_time\\\":\\\"0001-01-01T00:00:00Z\\\",\\\"deliver_all\\\":true,\\\"deliver_last\\\":true,\\\"ack_policy\\\":\\\"explicit\\\",\\\"ack_wait\\\":30000000000,\\\"filter_subject\\\":\\\"faas-cluster.faas-request\\\",\\\"replay_policy\\\":\\\"instant\\\"}}\",\n  \"response\": \"-ERR 'consumer starting position conflict'\"\n}"]
[13034] 2020/04/08 15:27:48.368015 [DBG] [::1]:55505 - cid:3 - Client connection closed
[13034] 2020/04/08 15:27:52.668169 [DBG] 127.0.0.1:55510 - cid:6 - Client connection created
[13034] 2020/04/08 15:27:52.668637 [TRC] 127.0.0.1:55510 - cid:6 - <<- [CONNECT {"verbose":false,"pedantic":false,"tls_required":false,"name":"NATS CLI","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
[13034] 2020/04/08 15:27:52.668665 [TRC] 127.0.0.1:55510 - cid:6 - <<- [PING]
[13034] 2020/04/08 15:27:52.668672 [TRC] 127.0.0.1:55510 - cid:6 - ->> [PONG]
[13034] 2020/04/08 15:27:52.668854 [TRC] 127.0.0.1:55510 - cid:6 - <<- [SUB _INBOX.J7eVraDHR9wJP3hNybVEgs  1]
[13034] 2020/04/08 15:27:52.668871 [TRC] 127.0.0.1:55510 - cid:6 - <<- [UNSUB 1 1]
[13034] 2020/04/08 15:27:52.668881 [TRC] 127.0.0.1:55510 - cid:6 - <<- [PUB $JS.STREAM.LIST _INBOX.J7eVraDHR9wJP3hNybVEgs 0]
[13034] 2020/04/08 15:27:52.668885 [TRC] 127.0.0.1:55510 - cid:6 - <<- MSG_PAYLOAD: [""]
[13034] 2020/04/08 15:27:52.668983 [TRC] SYSTEM - <<- [PUB _INBOX.J7eVraDHR9wJP3hNybVEgs  20]
[13034] 2020/04/08 15:27:52.668995 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["[\n  \"faas-cluster\"\n]"]
[13034] 2020/04/08 15:27:52.669012 [DBG] 127.0.0.1:55510 - cid:6 - Auto-unsubscribe limit of 1 reached for sid '1'
[13034] 2020/04/08 15:27:52.669021 [TRC] 127.0.0.1:55510 - cid:6 - ->> [MSG _INBOX.J7eVraDHR9wJP3hNybVEgs 1  20]
[13034] 2020/04/08 15:27:52.669025 [TRC] 127.0.0.1:55510 - cid:6 - <-> [DELSUB 1]
[13034] 2020/04/08 15:27:52.669039 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  446]
[13034] 2020/04/08 15:27:52.669049 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"wGC1NOc2rFowaApa3ydD7i\",\n  \"timestamp\": \"2020-04-08T19:27:52.668922Z\",\n  \"server\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n  \"client\": {\n    \"host\": \"127.0.0.1\",\n    \"port\": 55510,\n    \"cid\": 6,\n    \"account\": \"$G\",\n    \"name\": \"NATS CLI\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.1\"\n  },\n  \"subject\": \"$JS.STREAM.LIST\",\n  \"response\": \"[\\n  \\\"faas-cluster\\\"\\n]\"\n}"]
[13034] 2020/04/08 15:27:52.669434 [TRC] 127.0.0.1:55510 - cid:6 - <<- [SUB _INBOX.J7eVraDHR9wJP3hNybVEiR  2]
[13034] 2020/04/08 15:27:52.669456 [TRC] 127.0.0.1:55510 - cid:6 - <<- [UNSUB 2 1]
[13034] 2020/04/08 15:27:52.669470 [TRC] 127.0.0.1:55510 - cid:6 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.TEST.CREATE _INBOX.J7eVraDHR9wJP3hNybVEiR 252]
[13034] 2020/04/08 15:27:52.669484 [TRC] 127.0.0.1:55510 - cid:6 - <<- MSG_PAYLOAD: ["{\"stream_name\":\"faas-cluster\",\"config\":{\"delivery_subject\":\"\",\"durable_name\":\"TEST\",\"start_time\":\"0001-01-01T00:00:00Z\",\"deliver_last\":true,\"ack_policy\":\"explicit\",\"max_deliver\":-1,\"filter_subject\":\"faas-cluster.faas-reques\",\"replay_policy\":\"instant\"}}"]
[13034] 2020/04/08 15:27:54.947608 [DBG] 127.0.0.1:55510 - cid:6 - Client Ping Timer
[13034] 2020/04/08 15:27:54.947654 [TRC] 127.0.0.1:55510 - cid:6 - ->> [PING]
[13034] 2020/04/08 15:28:15.445822 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  662]
[13034] 2020/04/08 15:28:15.445871 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 3,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:28:15.445612-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 8871936,\n    \"cores\": 16,\n    \"cpu\": 99.2,\n    \"connections\": 1,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 59,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:28:45.446677 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:28:45.446751 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 4,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:28:45.446629-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9109504,\n    \"cores\": 16,\n    \"cpu\": 100.1,\n    \"connections\": 1,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 59,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:29:15.449158 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  662]
[13034] 2020/04/08 15:29:15.449263 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 5,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:29:15.449021-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9187328,\n    \"cores\": 16,\n    \"cpu\": 99.2,\n    \"connections\": 1,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 59,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:29:45.452298 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  662]
[13034] 2020/04/08 15:29:45.452332 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 6,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:29:45.452246-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9371648,\n    \"cores\": 16,\n    \"cpu\": 98.8,\n    \"connections\": 1,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 59,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:29:54.951463 [DBG] 127.0.0.1:55510 - cid:6 - Client Ping Timer
[13034] 2020/04/08 15:29:54.951491 [TRC] 127.0.0.1:55510 - cid:6 - ->> [PING]
[13034] 2020/04/08 15:29:54.951552 [DBG] 127.0.0.1:55510 - cid:6 - Error flushing: writev tcp 127.0.0.1:4222->127.0.0.1:55510: writev: broken pipe
[13034] 2020/04/08 15:29:54.951570 [DBG] 127.0.0.1:55510 - cid:6 - Client connection closed
[13034] 2020/04/08 15:29:54.951664 [TRC] 127.0.0.1:55510 - cid:6 - <-> [DELSUB 2]
[13034] 2020/04/08 15:30:15.457741 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  662]
[13034] 2020/04/08 15:30:15.457767 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 7,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:30:15.457692-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9449472,\n    \"cores\": 16,\n    \"cpu\": 99.5,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:30:45.460380 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:30:45.460453 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 8,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:30:45.460314-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9490432,\n    \"cores\": 16,\n    \"cpu\": 100.1,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:31:15.464184 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:31:15.464205 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 9,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:31:15.464142-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9572352,\n    \"cores\": 16,\n    \"cpu\": 100.1,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:31:45.468377 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:31:45.468403 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 10,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:31:45.468332-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9646080,\n    \"cores\": 16,\n    \"cpu\": 99.5,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:32:15.470393 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:32:15.470463 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 11,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:32:15.470307-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9707520,\n    \"cores\": 16,\n    \"cpu\": 98.8,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:32:45.474783 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  664]
[13034] 2020/04/08 15:32:45.474805 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 12,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:32:45.474727-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9801728,\n    \"cores\": 16,\n    \"cpu\": 100.1,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
[13034] 2020/04/08 15:33:15.482697 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP.STATSZ  663]
[13034] 2020/04/08 15:33:15.482724 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NAKMI4V4HHW5XAXHAZY4IE5X2EG7VAGSS3LNPTH2E4KUQO7VIKRNZGHP\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 13,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:33:15.482529-04:00\"\n  },\n  \"statsz\": {\n    \"start\": \"2020-04-08T15:27:45.437541-04:00\",\n    \"mem\": 9834496,\n    \"cores\": 16,\n    \"cpu\": 99.1,\n    \"connections\": 0,\n    \"total_connections\": 2,\n    \"active_accounts\": 2,\n    \"subscriptions\": 58,\n    \"sent\": {\n      \"msgs\": 7,\n      \"bytes\": 537\n    },\n    \"received\": {\n      \"msgs\": 7,\n      \"bytes\": 492\n    },\n    \"slow_consumers\": 0\n  }\n}"]
^\SIGQUIT: quit
PC=0x7fff66ca6ce6 m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x1a35908, 0x1a358c8, 0x7ffe00000000)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/sys_darwin.go:390 +0x39
runtime.semasleep(0xffffffffffffffff, 0x7ffeefbff420)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x1a356c8)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/lock_sema.go:173 +0xe0
runtime.stoplockedm()
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:1971 +0x88
runtime.schedule()
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:2454 +0x4a6
runtime.park_m(0xc000001b00)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:2690 +0x9d
runtime.mcall(0x1065ea6)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x2675f18, 0x72, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc000032798, 0x72, 0x0, 0x0, 0x15d244e)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000032780, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_unix.go:384 +0x1d4
net.(*netFD).accept(0xc000032780, 0x104010e, 0xc0000efc18, 0x10653f0)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc00000ff20, 0xc0000efc70, 0x1499ced, 0xc000000000)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc00000ff20, 0xc000198a01, 0xc0001860f0, 0x0, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/tcpsock.go:261 +0x64
github.com/nats-io/nats-server/v2/server.(*Server).AcceptLoop(0xc0000f8800, 0x0)
    /Users/matthiashanel/repos/nats-server/server/server.go:1509 +0x841
github.com/nats-io/nats-server/v2/server.(*Server).Start(0xc0000f8800)
    /Users/matthiashanel/repos/nats-server/server/server.go:1305 +0x95f
github.com/nats-io/nats-server/v2/server.Run(...)
    /Users/matthiashanel/repos/nats-server/server/service.go:21
main.main()
    /Users/matthiashanel/repos/nats-server/main.go:114 +0x141

goroutine 7 [syscall]:
os/signal.signal_recv(0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/sigqueue.go:144 +0x96
os/signal.loop()
    /usr/local/Cellar/go/1.14.1/libexec/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.Notify.func1
    /usr/local/Cellar/go/1.14.1/libexec/src/os/signal/signal.go:127 +0x44

goroutine 9 [select]:
github.com/nats-io/nats-server/v2/server.(*Server).handleSignals.func1(0xc00008a780, 0xc0000f8800)
    /Users/matthiashanel/repos/nats-server/server/signal.go:47 +0xbc
created by github.com/nats-io/nats-server/v2/server.(*Server).handleSignals
    /Users/matthiashanel/repos/nats-server/server/signal.go:45 +0x11a

goroutine 10 [select]:
github.com/nats-io/nats-server/v2/server.(*Server).startGWReplyMapExpiration.func1()
    /Users/matthiashanel/repos/nats-server/server/gateway.go:2973 +0x15b
created by github.com/nats-io/nats-server/v2/server.(*Server).startGoRoutine
    /Users/matthiashanel/repos/nats-server/server/server.go:2252 +0xad

goroutine 11 [select]:
github.com/nats-io/nats-server/v2/server.(*Server).internalSendLoop(0xc0000f8800, 0xc0000ba1f8)
    /Users/matthiashanel/repos/nats-server/server/events.go:242 +0x2d8
created by github.com/nats-io/nats-server/v2/server.(*Server).setSystemAccount
    /Users/matthiashanel/repos/nats-server/server/server.go:896 +0x2ab

goroutine 15 [select]:
github.com/nats-io/nats-server/v2/server.(*Stream).internalSendLoop(0xc00027c000)
    /Users/matthiashanel/repos/nats-server/server/stream.go:634 +0x1b3
created by github.com/nats-io/nats-server/v2/server.(*Stream).setupSendCapabilities
    /Users/matthiashanel/repos/nats-server/server/stream.go:602 +0xad

goroutine 34 [runnable]:
github.com/nats-io/nats-server/v2/server.(*Consumer).selectSubjectLast(0xc00042a000)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:1313 +0x152
github.com/nats-io/nats-server/v2/server.(*Consumer).selectStartingSeqNo(0xc00042a000)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:1334 +0xff
github.com/nats-io/nats-server/v2/server.(*Stream).AddConsumer(0xc00027c000, 0xc000426010, 0x4, 0xc000408101, 0x4)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:323 +0x612
github.com/nats-io/nats-server/v2/server.(*Server).jsCreateConsumerRequest(0xc0000f8800, 0xc0000bbef0, 0xc0001cd300, 0xc0004081b0, 0x2c, 0xc0004041c0, 0x1d, 0xc000302285, 0xfc, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/jetstream_api.go:580 +0x62b
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc0001cd300, 0xc0000bbef0, 0xc000408180, 0x2c, 0x30, 0xc0001cd5e9, 0x4b, 0x3ff, 0xc000302285, 0xfe, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:2503 +0x2f4
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc0001cd300, 0xc0002181c0, 0xc000414210, 0xc000302285, 0xfe, 0x17b, 0x0, 0x0, 0x0, 0xc000408180, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:3150 +0x720
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc0001cd300, 0xc00008be60, 0xc000218000, 0xc000302285, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/client.go:3016 +0x5ee
github.com/nats-io/nats-server/v2/server.(*Account).addServiceImportSub.func1(0xc00023d440, 0xc0001cd300, 0xc000408120, 0x2c, 0xc000404100, 0x1d, 0xc000302285, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/accounts.go:1047 +0x5e
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc0001cd300, 0xc00023d440, 0xc000302235, 0x2c, 0x1cb, 0xc0001cd5e9, 0x57, 0x3ff, 0xc000302285, 0xfe, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:2501 +0x3fa
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc0001cd300, 0xc000218000, 0xc000414150, 0xc000302285, 0xfe, 0x17b, 0x0, 0x0, 0x0, 0xc000302235, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:3150 +0x720
github.com/nats-io/nats-server/v2/server.(*client).processInboundClientMsg(0xc0001cd300, 0xc000302285, 0xfe, 0x17b, 0xc000400140)
    /Users/matthiashanel/repos/nats-server/server/client.go:2876 +0x520
github.com/nats-io/nats-server/v2/server.(*client).processInboundMsg(0xc0001cd300, 0xc000302285, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/client.go:2755 +0x95
github.com/nats-io/nats-server/v2/server.(*client).parse(0xc0001cd300, 0xc000302200, 0x183, 0x200, 0x183, 0x0)
    /Users/matthiashanel/repos/nats-server/server/parser.go:288 +0x17dc
github.com/nats-io/nats-server/v2/server.(*client).readLoop(0xc0001cd300)
    /Users/matthiashanel/repos/nats-server/server/client.go:908 +0x333
github.com/nats-io/nats-server/v2/server.(*Server).createClient.func2()
    /Users/matthiashanel/repos/nats-server/server/server.go:1896 +0x2a
created by github.com/nats-io/nats-server/v2/server.(*Server).startGoRoutine
    /Users/matthiashanel/repos/nats-server/server/server.go:2252 +0xad

rax    0x104
rbx    0x2
rcx    0x7ffeefbff248
rdx    0x1b00
rdi    0x1a35908
rsi    0x260100002700
rbp    0x7ffeefbff2e0
rsp    0x7ffeefbff248
r8     0x0
r9     0xa0
r10    0x0
r11    0x202
r12    0x1a35908
r13    0x16
r14    0x260100002700
r15    0x28b7dc0
rip    0x7fff66ca6ce6
rflags 0x203
cs     0x7
fs     0x0
gs     0x0

---------- Second try with ctrl c before dumping go routines

rm -rf test ; ./nats-server -js -DVV  -sd ./test
[13453] 2020/04/08 15:35:39.857073 [INF] Starting nats-server version 2.2.0-beta.7
[13453] 2020/04/08 15:35:39.857171 [DBG] Go build version go1.14.1
[13453] 2020/04/08 15:35:39.857174 [INF] Git commit [not set]
[13453] 2020/04/08 15:35:39.857184 [INF] Starting JetStream
[13453] 2020/04/08 15:35:39.857197 [DBG] JetStream creating dynamic configuration - 75% of system memory, 1.00 TB disk
[13453] 2020/04/08 15:35:39.857362 [DBG] Created system account: "$SYS"
[13453] 2020/04/08 15:35:39.857484 [TRC] SYSTEM - <<- [SUB $SYS._INBOX.2tAN4W.* 2]
[13453] 2020/04/08 15:35:39.857513 [TRC] SYSTEM - <<- [SUB $SYS.SERVER.ACCOUNT.*.CONNS 3]
[13453] 2020/04/08 15:35:39.857524 [TRC] SYSTEM - <<- [SUB $SYS._INBOX_.NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB 4]
[13453] 2020/04/08 15:35:39.857531 [TRC] SYSTEM - <<- [SUB $SYS.REQ.ACCOUNT.*.CONNS 5]
[13453] 2020/04/08 15:35:39.857536 [TRC] SYSTEM - <<- [SUB $SYS.REQ.ACCOUNT.NSUBS 6]
[13453] 2020/04/08 15:35:39.857540 [TRC] SYSTEM - <<- [SUB $SYS.SERVER.*.SHUTDOWN 7]
[13453] 2020/04/08 15:35:39.857544 [TRC] SYSTEM - <<- [SUB $SYS.ACCOUNT.*.CLAIMS.UPDATE 8]
[13453] 2020/04/08 15:35:39.857549 [TRC] SYSTEM - <<- [SUB $SYS.REQ.SERVER.NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB.STATSZ 9]
[13453] 2020/04/08 15:35:39.857556 [TRC] SYSTEM - <<- [SUB $SYS.REQ.SERVER.PING 10]
[13453] 2020/04/08 15:35:39.857564 [TRC] SYSTEM - <<- [SUB $SYS.ACCOUNT.*.LEAFNODE.CONNECT 11]
[13453] 2020/04/08 15:35:39.857569 [TRC] SYSTEM - <<- [SUB $SYS.LATENCY.M2.2tAN4W 12]
[13453] 2020/04/08 15:35:39.857573 [TRC] SYSTEM - <<- [SUB $SYS.DEBUG.SUBSCRIBERS 13]
[13453] 2020/04/08 15:35:39.857592 [TRC] SYSTEM - <<- [SUB $JS.ENABLED 14]
[13453] 2020/04/08 15:35:39.857604 [TRC] SYSTEM - <<- [SUB $JS.INFO 15]
[13453] 2020/04/08 15:35:39.857609 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.CREATE 16]
[13453] 2020/04/08 15:35:39.857613 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.LIST 17]
[13453] 2020/04/08 15:35:39.857617 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.INFO 18]
[13453] 2020/04/08 15:35:39.857621 [TRC] SYSTEM - <<- [SUB $JS.TEMPLATE.*.DELETE 19]
[13453] 2020/04/08 15:35:39.857624 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CREATE 20]
[13453] 2020/04/08 15:35:39.857663 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.UPDATE 21]
[13453] 2020/04/08 15:35:39.857676 [TRC] SYSTEM - <<- [SUB $JS.STREAM.LIST 22]
[13453] 2020/04/08 15:35:39.857684 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.INFO 23]
[13453] 2020/04/08 15:35:39.873109 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.DELETE 24]
[13453] 2020/04/08 15:35:39.857716 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.ACCOUNT.$SYS.CONNS  365]
[13453] 2020/04/08 15:35:39.873127 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.PURGE 25]
[13453] 2020/04/08 15:35:39.873136 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.MSG.DELETE 26]
[13453] 2020/04/08 15:35:39.873144 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.CREATE 27]
[13453] 2020/04/08 15:35:39.873149 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"server\": {\n    \"name\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n    \"host\": \"0.0.0.0\",\n    \"id\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n    \"ver\": \"2.2.0-beta.7\",\n    \"seq\": 2,\n    \"jetstream\": true,\n    \"time\": \"2020-04-08T15:35:39.85748-04:00\"\n  },\n  \"acc\": \"$SYS\",\n  \"conns\": 0,\n  \"leafnodes\": 0,\n  \"total_conns\": 0\n}"]
[13453] 2020/04/08 15:35:39.873149 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.EPHEMERAL.CONSUMER.CREATE 28]
[13453] 2020/04/08 15:35:39.873176 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMERS 29]
[13453] 2020/04/08 15:35:39.873188 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.INFO 30]
[13453] 2020/04/08 15:35:39.873194 [TRC] SYSTEM - <<- [SUB $JS.STREAM.*.CONSUMER.*.DELETE 31]
[13453] 2020/04/08 15:35:39.873199 [INF] ----------- JETSTREAM (Beta) -----------
[13453] 2020/04/08 15:35:39.873205 [INF]   Max Memory:      48.00 GB
[13453] 2020/04/08 15:35:39.873207 [INF]   Max Storage:     1.00 TB
[13453] 2020/04/08 15:35:39.873209 [INF]   Store Directory: "test/jetstream"
[13453] 2020/04/08 15:35:39.873211 [DBG]   Exports:
[13453] 2020/04/08 15:35:39.873213 [DBG]      $JS.ENABLED
[13453] 2020/04/08 15:35:39.873215 [DBG]      $JS.INFO
[13453] 2020/04/08 15:35:39.873216 [DBG]      $JS.TEMPLATE.*.CREATE
[13453] 2020/04/08 15:35:39.873218 [DBG]      $JS.TEMPLATE.LIST
[13453] 2020/04/08 15:35:39.873220 [DBG]      $JS.TEMPLATE.*.INFO
[13453] 2020/04/08 15:35:39.873222 [DBG]      $JS.TEMPLATE.*.DELETE
[13453] 2020/04/08 15:35:39.873224 [DBG]      $JS.STREAM.*.CREATE
[13453] 2020/04/08 15:35:39.873226 [DBG]      $JS.STREAM.*.UPDATE
[13453] 2020/04/08 15:35:39.873235 [DBG]      $JS.STREAM.LIST
[13453] 2020/04/08 15:35:39.873237 [DBG]      $JS.STREAM.*.INFO
[13453] 2020/04/08 15:35:39.873239 [DBG]      $JS.STREAM.*.DELETE
[13453] 2020/04/08 15:35:39.873240 [DBG]      $JS.STREAM.*.PURGE
[13453] 2020/04/08 15:35:39.873242 [DBG]      $JS.STREAM.*.MSG.DELETE
[13453] 2020/04/08 15:35:39.873251 [DBG]      $JS.STREAM.*.CONSUMER.*.CREATE
[13453] 2020/04/08 15:35:39.873253 [DBG]      $JS.STREAM.*.EPHEMERAL.CONSUMER.CREATE
[13453] 2020/04/08 15:35:39.873254 [DBG]      $JS.STREAM.*.CONSUMERS
[13453] 2020/04/08 15:35:39.873256 [DBG]      $JS.STREAM.*.CONSUMER.*.INFO
[13453] 2020/04/08 15:35:39.873258 [DBG]      $JS.STREAM.*.CONSUMER.*.DELETE
[13453] 2020/04/08 15:35:39.873259 [INF] ----------------------------------------
[13453] 2020/04/08 15:35:39.873333 [DBG] Enabled JetStream for account "$G"
[13453] 2020/04/08 15:35:39.873957 [DBG]   Max Memory:      48.00 GB
[13453] 2020/04/08 15:35:39.873963 [DBG]   Max Storage:     1.00 TB
[13453] 2020/04/08 15:35:39.873982 [INF]   Upgrading storage directory structure for "$G"
[13453] 2020/04/08 15:35:39.874152 [INF]   Recovering JetStream state for account "$G"
[13453] 2020/04/08 15:35:39.874243 [INF] JetStream state for account "$G" recovered
[13453] 2020/04/08 15:35:39.874406 [INF] Listening for client connections on 0.0.0.0:4222
[13453] 2020/04/08 15:35:39.874411 [INF] Server id is NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB
[13453] 2020/04/08 15:35:39.874412 [INF] Server is ready
[13453] 2020/04/08 15:35:39.874417 [DBG] Get non local IPs for "0.0.0.0"
[13453] 2020/04/08 15:35:39.874605 [DBG]   ip=2604:2000:1201:a4ca:c01:aab0:cbd4:cdee
[13453] 2020/04/08 15:35:39.874608 [DBG]   ip=2604:2000:1201:a4ca:ccd:e38c:b660:51eb
[13453] 2020/04/08 15:35:39.874610 [DBG]   ip=2604:2000:1201:a4ca::3fb
[13453] 2020/04/08 15:35:39.874613 [DBG]   ip=192.168.1.111
[13453] 2020/04/08 15:35:39.874614 [DBG]   ip=2604:2000:1201:a4ca:98a:277c:af08:fc99
[13453] 2020/04/08 15:35:39.874616 [DBG]   ip=2604:2000:1201:a4ca:8909:e45e:1d2e:1f03
[13453] 2020/04/08 15:35:39.874618 [DBG]   ip=2604:2000:1201:a4ca:4144:f953:6c7b:4d4
[13453] 2020/04/08 15:35:39.874620 [DBG]   ip=2604:2000:1201:a4ca:e4ac:2fe5:737f:f213
[13453] 2020/04/08 15:35:39.874726 [DBG]   ip=192.168.64.1
[13453] 2020/04/08 15:35:39.874730 [DBG]   ip=fd8a:db99:b964:cc77:14f0:15d0:3624:cc8e
[13453] 2020/04/08 15:35:39.874732 [DBG]   ip=fd8a:db99:b964:cc77:6163:e37f:e697:263
[13453] 2020/04/08 15:35:39.874734 [DBG]   ip=fd8a:db99:b964:cc77:ec83:59b9:fd49:cfa5
[13453] 2020/04/08 15:35:39.874736 [DBG]   ip=fd8a:db99:b964:cc77:285b:585a:fa66:b3a9
[13453] 2020/04/08 15:35:39.874738 [DBG]   ip=fd8a:db99:b964:cc77:c0fb:dc20:efe5:a2a5
[13453] 2020/04/08 15:35:39.874740 [DBG]   ip=fd8a:db99:b964:cc77:3d36:1b5f:ba53:baa5
[13453] 2020/04/08 15:35:44.208672 [DBG] [::1]:55647 - cid:3 - Client connection created
[13453] 2020/04/08 15:35:44.209510 [TRC] [::1]:55647 - cid:3 - <<- [CONNECT {"verbose":false,"pedantic":false,"tls_required":false,"name":"faas-worker-MacBook-Pro_local","lang":"go","version":"1.9.2","protocol":1,"echo":true}]
[13453] 2020/04/08 15:35:44.209652 [TRC] [::1]:55647 - cid:3 - <<- [PING]
[13453] 2020/04/08 15:35:44.209662 [TRC] [::1]:55647 - cid:3 - ->> [PONG]
[13453] 2020/04/08 15:35:44.209927 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFaq  1]
[13453] 2020/04/08 15:35:44.209951 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 1 1]
[13453] 2020/04/08 15:35:44.209958 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.ENABLED _INBOX.d2Usk0lAaxqk1iAcJPwFaq 0]
[13453] 2020/04/08 15:35:44.209963 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: [""]
[13453] 2020/04/08 15:35:44.210143 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFaq  3]
[13453] 2020/04/08 15:35:44.210152 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["+OK"]
[13453] 2020/04/08 15:35:44.210171 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '1'
[13453] 2020/04/08 15:35:44.210176 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFaq 1  3]
[13453] 2020/04/08 15:35:44.210179 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 1]
[13453] 2020/04/08 15:35:44.210357 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  436]
[13453] 2020/04/08 15:35:44.210382 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbCS\",\n  \"timestamp\": \"2020-04-08T19:35:44.210089Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.ENABLED\",\n  \"response\": \"+OK\"\n}"]
[13453] 2020/04/08 15:35:44.210391 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFbk  2]
[13453] 2020/04/08 15:35:44.210419 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 2 1]
[13453] 2020/04/08 15:35:44.210426 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.INFO _INBOX.d2Usk0lAaxqk1iAcJPwFbk 0]
[13453] 2020/04/08 15:35:44.210431 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: [""]
[13453] 2020/04/08 15:35:44.210506 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFbk  23]
[13453] 2020/04/08 15:35:44.210517 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'stream not found'"]
[13453] 2020/04/08 15:35:44.210526 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '2'
[13453] 2020/04/08 15:35:44.210532 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFbk 2  23]
[13453] 2020/04/08 15:35:44.210535 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 2]
[13453] 2020/04/08 15:35:44.210554 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  472]
[13453] 2020/04/08 15:35:44.210589 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbEB\",\n  \"timestamp\": \"2020-04-08T19:35:44.21047Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.INFO\",\n  \"response\": \"-ERR 'stream not found'\"\n}"]
[13453] 2020/04/08 15:35:44.210858 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFce  3]
[13453] 2020/04/08 15:35:44.210871 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 3 1]
[13453] 2020/04/08 15:35:44.210881 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CREATE _INBOX.d2Usk0lAaxqk1iAcJPwFce 214]
[13453] 2020/04/08 15:35:44.210898 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: ["{\"name\":\"faas-cluster\",\"subjects\":[\"faas-cluster.\\u003e\"],\"retention\":\"limits\",\"max_consumers\":-1,\"max_msgs\":-1,\"max_bytes\":1048576,\"max_age\":31536000000000000,\"max_msg_size\":-1,\"storage\":\"memory\",\"num_replicas\":1}"]
[13453] 2020/04/08 15:35:44.211116 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFce  3]
[13453] 2020/04/08 15:35:44.211125 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["+OK"]
[13453] 2020/04/08 15:35:44.211144 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '3'
[13453] 2020/04/08 15:35:44.211150 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFce 3  3]
[13453] 2020/04/08 15:35:44.211155 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 3]
[13453] 2020/04/08 15:35:44.211167 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  715]
[13453] 2020/04/08 15:35:44.211194 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbFu\",\n  \"timestamp\": \"2020-04-08T19:35:44.211078Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CREATE\",\n  \"request\": \"{\\\"name\\\":\\\"faas-cluster\\\",\\\"subjects\\\":[\\\"faas-cluster.\\\\u003e\\\"],\\\"retention\\\":\\\"limits\\\",\\\"max_consumers\\\":-1,\\\"max_msgs\\\":-1,\\\"max_bytes\\\":1048576,\\\"max_age\\\":31536000000000000,\\\"max_msg_size\\\":-1,\\\"storage\\\":\\\"memory\\\",\\\"num_replicas\\\":1}\",\n  \"response\": \"+OK\"\n}"]
[13453] 2020/04/08 15:35:44.211314 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFdY  4]
[13453] 2020/04/08 15:35:44.211328 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 4 1]
[13453] 2020/04/08 15:35:44.211334 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.INFO _INBOX.d2Usk0lAaxqk1iAcJPwFdY 0]
[13453] 2020/04/08 15:35:44.211339 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: [""]
[13453] 2020/04/08 15:35:44.211486 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFdY  421]
[13453] 2020/04/08 15:35:44.211502 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"config\": {\n    \"name\": \"faas-cluster\",\n    \"subjects\": [\n      \"faas-cluster.\\u003e\"\n    ],\n    \"retention\": \"limits\",\n    \"max_consumers\": -1,\n    \"max_msgs\": -1,\n    \"max_bytes\": 1048576,\n    \"max_age\": 31536000000000000,\n    \"max_msg_size\": -1,\n    \"storage\": \"memory\",\n    \"num_replicas\": 1\n  },\n  \"state\": {\n    \"messages\": 0,\n    \"bytes\": 0,\n    \"first_seq\": 0,\n    \"last_seq\": 0,\n    \"consumer_count\": 0\n  }\n}"]
[13453] 2020/04/08 15:35:44.211509 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '4'
[13453] 2020/04/08 15:35:44.211513 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFdY 4  421]
[13453] 2020/04/08 15:35:44.211516 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 4]
[13453] 2020/04/08 15:35:44.211524 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  936]
[13453] 2020/04/08 15:35:44.211571 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbHd\",\n  \"timestamp\": \"2020-04-08T19:35:44.211445Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.INFO\",\n  \"response\": \"{\\n  \\\"config\\\": {\\n    \\\"name\\\": \\\"faas-cluster\\\",\\n    \\\"subjects\\\": [\\n      \\\"faas-cluster.\\\\u003e\\\"\\n    ],\\n    \\\"retention\\\": \\\"limits\\\",\\n    \\\"max_consumers\\\": -1,\\n    \\\"max_msgs\\\": -1,\\n    \\\"max_bytes\\\": 1048576,\\n    \\\"max_age\\\": 31536000000000000,\\n    \\\"max_msg_size\\\": -1,\\n    \\\"storage\\\": \\\"memory\\\",\\n    \\\"num_replicas\\\": 1\\n  },\\n  \\\"state\\\": {\\n    \\\"messages\\\": 0,\\n    \\\"bytes\\\": 0,\\n    \\\"first_seq\\\": 0,\\n    \\\"last_seq\\\": 0,\\n    \\\"consumer_count\\\": 0\\n  }\\n}\"\n}"]
[13453] 2020/04/08 15:35:44.211742 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFeS  5]
[13453] 2020/04/08 15:35:44.211765 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 5 1]
[13453] 2020/04/08 15:35:44.211772 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.faas.INFO _INBOX.d2Usk0lAaxqk1iAcJPwFeS 0]
[13453] 2020/04/08 15:35:44.211776 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: [""]
[13453] 2020/04/08 15:35:44.211843 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFeS  25]
[13453] 2020/04/08 15:35:44.211852 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'consumer not found'"]
[13453] 2020/04/08 15:35:44.211858 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '5'
[13453] 2020/04/08 15:35:44.211862 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFeS 5  25]
[13453] 2020/04/08 15:35:44.211867 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 5]
[13453] 2020/04/08 15:35:44.211880 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  489]
[13453] 2020/04/08 15:35:44.211914 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbJM\",\n  \"timestamp\": \"2020-04-08T19:35:44.211811Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CONSUMER.faas.INFO\",\n  \"response\": \"-ERR 'consumer not found'\"\n}"]
[13453] 2020/04/08 15:35:44.212089 [TRC] [::1]:55647 - cid:3 - <<- [SUB _INBOX.d2Usk0lAaxqk1iAcJPwFfM  6]
[13453] 2020/04/08 15:35:44.212105 [TRC] [::1]:55647 - cid:3 - <<- [UNSUB 6 1]
[13453] 2020/04/08 15:35:44.212117 [TRC] [::1]:55647 - cid:3 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.faas.CREATE _INBOX.d2Usk0lAaxqk1iAcJPwFfM 278]
[13453] 2020/04/08 15:35:44.212134 [TRC] [::1]:55647 - cid:3 - <<- MSG_PAYLOAD: ["{\"stream_name\":\"faas-cluster\",\"config\":{\"delivery_subject\":\"\",\"durable_name\":\"faas\",\"start_time\":\"0001-01-01T00:00:00Z\",\"deliver_all\":true,\"deliver_last\":true,\"ack_policy\":\"explicit\",\"ack_wait\":30000000000,\"filter_subject\":\"faas-cluster.faas-request\",\"replay_policy\":\"instant\"}}"]
[13453] 2020/04/08 15:35:44.212286 [TRC] SYSTEM - <<- [PUB _INBOX.d2Usk0lAaxqk1iAcJPwFfM  42]
[13453] 2020/04/08 15:35:44.212298 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["-ERR 'consumer starting position conflict'"]
[13453] 2020/04/08 15:35:44.212306 [DBG] [::1]:55647 - cid:3 - Auto-unsubscribe limit of 1 reached for sid '6'
[13453] 2020/04/08 15:35:44.212311 [TRC] [::1]:55647 - cid:3 - ->> [MSG _INBOX.d2Usk0lAaxqk1iAcJPwFfM 6  42]
[13453] 2020/04/08 15:35:44.212316 [TRC] [::1]:55647 - cid:3 - <-> [DELSUB 6]
[13453] 2020/04/08 15:35:44.212327 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  839]
[13453] 2020/04/08 15:35:44.212371 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbL5\",\n  \"timestamp\": \"2020-04-08T19:35:44.212243Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"::1\",\n    \"port\": 55647,\n    \"cid\": 3,\n    \"account\": \"$G\",\n    \"name\": \"faas-worker-MacBook-Pro_local\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.2\"\n  },\n  \"subject\": \"$JS.STREAM.faas-cluster.CONSUMER.faas.CREATE\",\n  \"request\": \"{\\\"stream_name\\\":\\\"faas-cluster\\\",\\\"config\\\":{\\\"delivery_subject\\\":\\\"\\\",\\\"durable_name\\\":\\\"faas\\\",\\\"start_time\\\":\\\"0001-01-01T00:00:00Z\\\",\\\"deliver_all\\\":true,\\\"deliver_last\\\":true,\\\"ack_policy\\\":\\\"explicit\\\",\\\"ack_wait\\\":30000000000,\\\"filter_subject\\\":\\\"faas-cluster.faas-request\\\",\\\"replay_policy\\\":\\\"instant\\\"}}\",\n  \"response\": \"-ERR 'consumer starting position conflict'\"\n}"]
[13453] 2020/04/08 15:35:44.215799 [DBG] [::1]:55647 - cid:3 - Client connection closed
[13453] 2020/04/08 15:35:50.220530 [DBG] 127.0.0.1:55651 - cid:6 - Client connection created
[13453] 2020/04/08 15:35:50.221005 [TRC] 127.0.0.1:55651 - cid:6 - <<- [CONNECT {"verbose":false,"pedantic":false,"tls_required":false,"name":"NATS CLI","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
[13453] 2020/04/08 15:35:50.221030 [TRC] 127.0.0.1:55651 - cid:6 - <<- [PING]
[13453] 2020/04/08 15:35:50.221033 [TRC] 127.0.0.1:55651 - cid:6 - ->> [PONG]
[13453] 2020/04/08 15:35:50.221206 [TRC] 127.0.0.1:55651 - cid:6 - <<- [SUB _INBOX.dsgQQtgbY65PMqSNclq2rz  1]
[13453] 2020/04/08 15:35:50.221226 [TRC] 127.0.0.1:55651 - cid:6 - <<- [UNSUB 1 1]
[13453] 2020/04/08 15:35:50.221230 [TRC] 127.0.0.1:55651 - cid:6 - <<- [PUB $JS.STREAM.LIST _INBOX.dsgQQtgbY65PMqSNclq2rz 0]
[13453] 2020/04/08 15:35:50.221234 [TRC] 127.0.0.1:55651 - cid:6 - <<- MSG_PAYLOAD: [""]
[13453] 2020/04/08 15:35:50.221309 [TRC] SYSTEM - <<- [PUB _INBOX.dsgQQtgbY65PMqSNclq2rz  20]
[13453] 2020/04/08 15:35:50.221317 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["[\n  \"faas-cluster\"\n]"]
[13453] 2020/04/08 15:35:50.221325 [DBG] 127.0.0.1:55651 - cid:6 - Auto-unsubscribe limit of 1 reached for sid '1'
[13453] 2020/04/08 15:35:50.221330 [TRC] 127.0.0.1:55651 - cid:6 - ->> [MSG _INBOX.dsgQQtgbY65PMqSNclq2rz 1  20]
[13453] 2020/04/08 15:35:50.221336 [TRC] 127.0.0.1:55651 - cid:6 - <-> [DELSUB 1]
[13453] 2020/04/08 15:35:50.221346 [TRC] SYSTEM - <<- [PUB $JS.EVENT.ADVISORY.API  446]
[13453] 2020/04/08 15:35:50.221355 [TRC] SYSTEM - <<- MSG_PAYLOAD: ["{\n  \"schema\": \"io.nats.jetstream.advisory.v1.api_audit\",\n  \"id\": \"a4pfmPBgQ04FzzdcvKdbMo\",\n  \"timestamp\": \"2020-04-08T19:35:50.221267Z\",\n  \"server\": \"NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB\",\n  \"client\": {\n    \"host\": \"127.0.0.1\",\n    \"port\": 55651,\n    \"cid\": 6,\n    \"account\": \"$G\",\n    \"name\": \"NATS CLI\",\n    \"lang\": \"go\",\n    \"version\": \"1.9.1\"\n  },\n  \"subject\": \"$JS.STREAM.LIST\",\n  \"response\": \"[\\n  \\\"faas-cluster\\\"\\n]\"\n}"]
[13453] 2020/04/08 15:35:50.221598 [TRC] 127.0.0.1:55651 - cid:6 - <<- [SUB _INBOX.dsgQQtgbY65PMqSNclq2u2  2]
[13453] 2020/04/08 15:35:50.221610 [TRC] 127.0.0.1:55651 - cid:6 - <<- [UNSUB 2 1]
[13453] 2020/04/08 15:35:50.221614 [TRC] 127.0.0.1:55651 - cid:6 - <<- [PUB $JS.STREAM.faas-cluster.CONSUMER.TEST.CREATE _INBOX.dsgQQtgbY65PMqSNclq2u2 252]
[13453] 2020/04/08 15:35:50.221622 [TRC] 127.0.0.1:55651 - cid:6 - <<- MSG_PAYLOAD: ["{\"stream_name\":\"faas-cluster\",\"config\":{\"delivery_subject\":\"\",\"durable_name\":\"TEST\",\"start_time\":\"0001-01-01T00:00:00Z\",\"deliver_last\":true,\"ack_policy\":\"explicit\",\"max_deliver\":-1,\"filter_subject\":\"faas-cluster.faas-reques\",\"replay_policy\":\"instant\"}}"]
[13453] 2020/04/08 15:35:52.532969 [DBG] 127.0.0.1:55651 - cid:6 - Client Ping Timer
[13453] 2020/04/08 15:35:52.532999 [TRC] 127.0.0.1:55651 - cid:6 - ->> [PING]
^C[13453] 2020/04/08 15:35:54.961196 [DBG] Trapped "interrupt" signal
[13453] 2020/04/08 15:35:54.961226 [TRC] SYSTEM - <<- [PUB $SYS.SERVER.NCUOB4Z4XWXZ3XUG35G4BA7STA3DZUKENBSUOIGU5DFLD6BEQR3YU7NB.SHUTDOWN  0]
[13453] 2020/04/08 15:35:54.961232 [TRC] SYSTEM - <<- MSG_PAYLOAD: [""]
^\SIGQUIT: quit
PC=0x7fff66ca6ce6 m=0 sigcode=0

goroutine 0 [idle]:
runtime.pthread_cond_wait(0x1a35908, 0x1a358c8, 0x7ffe00000000)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/sys_darwin.go:390 +0x39
runtime.semasleep(0xffffffffffffffff, 0x7ffeefbff420)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/os_darwin.go:63 +0x85
runtime.notesleep(0x1a356c8)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/lock_sema.go:173 +0xe0
runtime.stoplockedm()
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:1971 +0x88
runtime.schedule()
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:2454 +0x4a6
runtime.park_m(0xc000001680)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/proc.go:2690 +0x9d
runtime.mcall(0x1065ea6)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/asm_amd64.s:318 +0x5b

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x7c39f18, 0x72, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc000204198, 0x72, 0x0, 0x0, 0x15d244e)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc000204180, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/internal/poll/fd_unix.go:384 +0x1d4
net.(*netFD).accept(0xc000204180, 0x104010e, 0xc000185c18, 0x10653f0)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc000206c40, 0xc000185c70, 0x1499ced, 0xc000000000)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc000206c40, 0xc000129101, 0xc000130168, 0x0, 0x0)
    /usr/local/Cellar/go/1.14.1/libexec/src/net/tcpsock.go:261 +0x64
github.com/nats-io/nats-server/v2/server.(*Server).AcceptLoop(0xc0000ba000, 0x0)
    /Users/matthiashanel/repos/nats-server/server/server.go:1509 +0x841
github.com/nats-io/nats-server/v2/server.(*Server).Start(0xc0000ba000)
    /Users/matthiashanel/repos/nats-server/server/server.go:1305 +0x95f
github.com/nats-io/nats-server/v2/server.Run(...)
    /Users/matthiashanel/repos/nats-server/server/service.go:21
main.main()
    /Users/matthiashanel/repos/nats-server/main.go:114 +0x141

goroutine 37 [select]:
github.com/nats-io/nats-server/v2/server.(*Stream).internalSendLoop(0xc000328000)
    /Users/matthiashanel/repos/nats-server/server/stream.go:634 +0x1b3
created by github.com/nats-io/nats-server/v2/server.(*Stream).setupSendCapabilities
    /Users/matthiashanel/repos/nats-server/server/stream.go:602 +0xad

goroutine 5 [syscall]:
os/signal.signal_recv(0x16a22e0)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/sigqueue.go:144 +0x96
os/signal.loop()
    /usr/local/Cellar/go/1.14.1/libexec/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.Notify.func1
    /usr/local/Cellar/go/1.14.1/libexec/src/os/signal/signal.go:127 +0x44

goroutine 7 [semacquire]:
sync.runtime_SemacquireMutex(0xc000328004, 0x0, 0x1)
    /usr/local/Cellar/go/1.14.1/libexec/src/runtime/sema.go:71 +0x47
sync.(*Mutex).lockSlow(0xc000328000)
    /usr/local/Cellar/go/1.14.1/libexec/src/sync/mutex.go:138 +0xfc
sync.(*Mutex).Lock(...)
    /usr/local/Cellar/go/1.14.1/libexec/src/sync/mutex.go:81
sync.(*RWMutex).Lock(0xc000328000)
    /usr/local/Cellar/go/1.14.1/libexec/src/sync/rwmutex.go:98 +0x97
github.com/nats-io/nats-server/v2/server.(*Stream).stop(0xc000328000, 0x0, 0xc000182b88, 0x0)
    /Users/matthiashanel/repos/nats-server/server/stream.go:666 +0x42
github.com/nats-io/nats-server/v2/server.(*jsAccount).delete(0xc000262000)
    /Users/matthiashanel/repos/nats-server/server/jetstream.go:720 +0x30a
github.com/nats-io/nats-server/v2/server.(*jetStream).disableJetStream(0xc00008a5a0, 0xc000262000, 0xc000182cb8, 0x0)
    /Users/matthiashanel/repos/nats-server/server/jetstream.go:619 +0xa7
github.com/nats-io/nats-server/v2/server.(*Server).shutdownJetStream(0xc0000ba000)
    /Users/matthiashanel/repos/nats-server/server/jetstream.go:198 +0x1e9
github.com/nats-io/nats-server/v2/server.(*Server).Shutdown(0xc0000ba000)
    /Users/matthiashanel/repos/nats-server/server/server.go:1318 +0x54
github.com/nats-io/nats-server/v2/server.(*Server).handleSignals.func1(0xc00008a480, 0xc0000ba000)
    /Users/matthiashanel/repos/nats-server/server/signal.go:52 +0x30f
created by github.com/nats-io/nats-server/v2/server.(*Server).handleSignals
    /Users/matthiashanel/repos/nats-server/server/signal.go:45 +0x11a

goroutine 8 [select]:
github.com/nats-io/nats-server/v2/server.(*Server).startGWReplyMapExpiration.func1()
    /Users/matthiashanel/repos/nats-server/server/gateway.go:2973 +0x15b
created by github.com/nats-io/nats-server/v2/server.(*Server).startGoRoutine
    /Users/matthiashanel/repos/nats-server/server/server.go:2252 +0xad

goroutine 38 [runnable]:
github.com/nats-io/nats-server/v2/server.(*memStore).LoadMsg(0xc0003280e0, 0xffffffffb2ee08cd, 0xc000076440, 0x0, 0x0, 0x0, 0x0, 0x0, 0x169ce00, 0xc000076450)
    /Users/matthiashanel/repos/nats-server/server/memstore.go:239 +0x1a2
github.com/nats-io/nats-server/v2/server.(*Consumer).selectSubjectLast(0xc0001da000)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:1312 +0xae
github.com/nats-io/nats-server/v2/server.(*Consumer).selectStartingSeqNo(0xc0001da000)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:1334 +0xff
github.com/nats-io/nats-server/v2/server.(*Stream).AddConsumer(0xc000328000, 0xc00013f0f0, 0x4, 0xc000136b01, 0x4)
    /Users/matthiashanel/repos/nats-server/server/consumer.go:323 +0x612
github.com/nats-io/nats-server/v2/server.(*Server).jsCreateConsumerRequest(0xc0000ba000, 0xc0002385a0, 0xc0001a5300, 0xc000136b40, 0x2c, 0xc0001411c0, 0x1d, 0xc000318685, 0xfc, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/jetstream_api.go:580 +0x62b
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc0001a5300, 0xc0002385a0, 0xc000136b10, 0x2c, 0x30, 0xc0001a55e9, 0x4b, 0x3ff, 0xc000318685, 0xfe, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:2503 +0x2f4
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc0001a5300, 0xc0000d41c0, 0xc0001ca960, 0xc000318685, 0xfe, 0x17b, 0x0, 0x0, 0x0, 0xc000136b10, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:3150 +0x720
github.com/nats-io/nats-server/v2/server.(*client).processServiceImport(0xc0001a5300, 0xc00021cf00, 0xc0000d4000, 0xc000318685, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/client.go:3016 +0x5ee
github.com/nats-io/nats-server/v2/server.(*Account).addServiceImportSub.func1(0xc000239a70, 0xc0001a5300, 0xc000136ab0, 0x2c, 0xc000141100, 0x1d, 0xc000318685, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/accounts.go:1047 +0x5e
github.com/nats-io/nats-server/v2/server.(*client).deliverMsg(0xc0001a5300, 0xc000239a70, 0xc000318635, 0x2c, 0x1cb, 0xc0001a55e9, 0x57, 0x3ff, 0xc000318685, 0xfe, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:2501 +0x3fa
github.com/nats-io/nats-server/v2/server.(*client).processMsgResults(0xc0001a5300, 0xc0000d4000, 0xc0001ca8a0, 0xc000318685, 0xfe, 0x17b, 0x0, 0x0, 0x0, 0xc000318635, ...)
    /Users/matthiashanel/repos/nats-server/server/client.go:3150 +0x720
github.com/nats-io/nats-server/v2/server.(*client).processInboundClientMsg(0xc0001a5300, 0xc000318685, 0xfe, 0x17b, 0xc000129440)
    /Users/matthiashanel/repos/nats-server/server/client.go:2876 +0x520
github.com/nats-io/nats-server/v2/server.(*client).processInboundMsg(0xc0001a5300, 0xc000318685, 0xfe, 0x17b)
    /Users/matthiashanel/repos/nats-server/server/client.go:2755 +0x95
github.com/nats-io/nats-server/v2/server.(*client).parse(0xc0001a5300, 0xc000318600, 0x183, 0x200, 0x183, 0x0)
    /Users/matthiashanel/repos/nats-server/server/parser.go:288 +0x17dc
github.com/nats-io/nats-server/v2/server.(*client).readLoop(0xc0001a5300)
    /Users/matthiashanel/repos/nats-server/server/client.go:908 +0x333
github.com/nats-io/nats-server/v2/server.(*Server).createClient.func2()
    /Users/matthiashanel/repos/nats-server/server/server.go:1896 +0x2a
created by github.com/nats-io/nats-server/v2/server.(*Server).startGoRoutine
    /Users/matthiashanel/repos/nats-server/server/server.go:2252 +0xad

goroutine 39 [select]:
github.com/nats-io/nats-server/v2/server.(*client).writeLoop(0xc0001a5300)
    /Users/matthiashanel/repos/nats-server/server/client.go:797 +0x303
github.com/nats-io/nats-server/v2/server.(*Server).createClient.func3()
    /Users/matthiashanel/repos/nats-server/server/server.go:1899 +0x2a
created by github.com/nats-io/nats-server/v2/server.(*Server).startGoRoutine
    /Users/matthiashanel/repos/nats-server/server/server.go:2252 +0xad

rax    0x104
rbx    0x2
rcx    0x7ffeefbff248
rdx    0x1b00
rdi    0x1a35908
rsi    0x1c0100001d00
rbp    0x7ffeefbff2e0
rsp    0x7ffeefbff248
r8     0x0
r9     0xa0
r10    0x0
r11    0x202
r12    0x1a35908
r13    0x16
r14    0x1c0100001d00
r15    0x7df8dc0
rip    0x7fff66ca6ce6
rflags 0x203
cs     0x7
fs     0x0
gs     0x0
derekcollison commented 4 years ago

Thanks will take a look.

derekcollison commented 4 years ago

I see it is requesting deliverAll and deliverLast which it properly errors on, you can only chose one. But it must not clean it self up properly or something..

ripienaar commented 4 years ago

On jsm side I will be more careful about these combos, will check tomorrow

derekcollison commented 4 years ago

Might also be the advisory being generated.. Will check it out.

matthiashanel commented 4 years ago

Yes I realized that this is what is going on inside the server. I do not explicitly set both...

In general can we improve the errors returned? Currently we return a generic error, can we add details? (: ) This is probably a bigger issue and came up on the ngs prod slack today as well.

ripienaar commented 4 years ago

jsm uses a starting template and merged your options with that template. I wasn’t careful to avoid impossible combos there

Regardless server needs to not do what it does. I have worked on better errors but people don’t seem to like it (myself included)

derekcollison commented 4 years ago

I will fix server issue.

derekcollison commented 4 years ago

ok fixed in jetstream branch.

matthiashanel commented 4 years ago

That seems to have done it.

matthiashanel commented 4 years ago

@ripienaar , I created a separate issue for the jsm library. Personally I'd fix this by making it impossible through changing the format altogether. Similar for consumer options.