nats-server: Service crossing accounts and leaf nodes can't send message back to requester.

  • Defect
  • Feature Request or Change Proposal

Defects

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

  • Included nats-server -DV output
c1          | [1372] 2020/01/10 15:17:46.476336 [INF] Starting nats-server version 2.1.2
c1          | [1372] 2020/01/10 15:17:46.476336 [DBG] Go build version go1.12.13
c1          | [1372] 2020/01/10 15:17:46.476336 [INF] Git commit [679beda]
c1          | [1372] 2020/01/10 15:17:46.476336 [WRN] Plaintext passwords detected, use nkeys or bcrypt.
c1          | [1372] 2020/01/10 15:17:46.478337 [INF] Starting http monitor on 0.0.0.0:8222
c1          | [1372] 2020/01/10 15:17:46.478337 [INF] Listening for leafnode connections on 0.0.0.0:7422
c1          | [1372] 2020/01/10 15:17:46.478337 [DBG] Get non local IPs for "0.0.0.0"
c1          | [1372] 2020/01/10 15:17:46.485338 [DBG]  ip=172.18.206.186
c1          | [1372] 2020/01/10 15:17:46.488338 [INF] Listening for client connections on 0.0.0.0:4244
c1          | [1372] 2020/01/10 15:17:46.488338 [INF] Server id is ND2MSDWDWTMJEX2V7TDS2O53Q5ZEY3W3ORS6T53HOM3PR5BBP6ZSYCA6
c1          | [1372] 2020/01/10 15:17:46.488338 [INF] Server is ready
c1          | [1372] 2020/01/10 15:17:46.488338 [DBG] Get non local IPs for "0.0.0.0"
c1          | [1372] 2020/01/10 15:17:46.492338 [DBG]  ip=172.18.206.186
c2          | [1372] 2020/01/10 15:17:48.537218 [INF] Starting nats-server version 2.1.2
c2          | [1372] 2020/01/10 15:17:48.537218 [DBG] Go build version go1.12.13
c2          | [1372] 2020/01/10 15:17:48.537218 [INF] Git commit [679beda]
c2          | [1372] 2020/01/10 15:17:48.537218 [WRN] Plaintext passwords detected, use nkeys or bcrypt.
c2          | [1372] 2020/01/10 15:17:48.539218 [INF] Starting http monitor on 0.0.0.0:8222
c2          | [1372] 2020/01/10 15:17:48.539218 [INF] Listening for client connections on 0.0.0.0:4244
c2          | [1372] 2020/01/10 15:17:48.539218 [INF] Server id is NCIHCZWAIQUH3OK624BMEV62WEEX6IEBKUFXAPRFRCE3GVEWRRNC5WBX
c2          | [1372] 2020/01/10 15:17:48.539218 [INF] Server is ready
c2          | [1372] 2020/01/10 15:17:48.539218 [DBG] Get non local IPs for "0.0.0.0"
c2          | [1372] 2020/01/10 15:17:48.545215 [DBG]  ip=172.18.194.70
c2          | [1372] 2020/01/10 15:17:48.556228 [DBG] Trying to connect as leafnode to remote server on "c1:7422" (172.18.206.186:7422)
c1          | [1372] 2020/01/10 15:17:48.560110 [DBG] 172.18.194.70:49157 - lid:1 - Leafnode connection created
c2          | [1372] 2020/01/10 15:17:48.560661 [DBG] 172.18.206.186:7422 - lid:1 - Remote leafnode connect msg sent
c2          | [1372] 2020/01/10 15:17:48.560661 [DBG] 172.18.206.186:7422 - lid:1 - Leafnode connection created
c2          | [1372] 2020/01/10 15:17:48.560661 [INF] Connected leafnode to "c1"
c1          | [1372] 2020/01/10 15:17:48.561188 [TRC] 172.18.194.70:49157 - lid:1 - <<- [CONNECT {"tls_required":false,"name":"NCIHCZWAIQUH3OK624BMEV62WEEX6IEBKUFXAPRFRCE3GVEWRRNC5WBX"}]
c1          | [1372] 2020/01/10 15:17:48.562131 [TRC] 172.18.194.70:49157 - lid:1 - ->> [LS+ test.service.1]
c1          | [1372] 2020/01/10 15:17:48.562131 [TRC] 172.18.194.70:49157 - lid:1 - ->> [LS+ lds.qtioyTeG9dZPgE8uYM7rsy]
c2          | [1372] 2020/01/10 15:17:48.561759 [TRC] 172.18.206.186:7422 - lid:1 - <<- [LS+ test.service.1]
c2          | [1372] 2020/01/10 15:17:48.562839 [TRC] 172.18.206.186:7422 - lid:1 - <<- [LS+ lds.qtioyTeG9dZPgE8uYM7rsy]
c1          | [1372] 2020/01/10 15:17:49.489505 [DBG] 10.35.68.24:62849 - cid:2 - Client connection created
c1          | [1372] 2020/01/10 15:17:49.491212 [TRC] 10.35.68.24:62849 - cid:2 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"a","pass":"[REDACTED]","tls_required":false,"name":"NATS Sample Responder","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
c1          | [1372] 2020/01/10 15:17:49.491212 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PING]
c1          | [1372] 2020/01/10 15:17:49.491212 [TRC] 10.35.68.24:62849 - cid:2 - ->> [PONG]
c1          | [1372] 2020/01/10 15:17:49.491563 [TRC] 10.35.68.24:62849 - cid:2 - <<- [SUB test.service.1 NATS-RPLY-22 1]
c1          | [1372] 2020/01/10 15:17:49.491563 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PING]
c1          | [1372] 2020/01/10 15:17:49.491563 [TRC] 10.35.68.24:62849 - cid:2 - ->> [PONG]
c2          | [1372] 2020/01/10 15:17:49.636028 [DBG] 172.18.206.186:7422 - lid:1 - LeafNode Ping Timer
c2          | [1372] 2020/01/10 15:17:49.636282 [TRC] 172.18.206.186:7422 - lid:1 - ->> [PING]
c1          | [1372] 2020/01/10 15:17:49.636909 [TRC] 172.18.194.70:49157 - lid:1 - <<- [PING]
c1          | [1372] 2020/01/10 15:17:49.636909 [TRC] 172.18.194.70:49157 - lid:1 - ->> [PONG]
c2          | [1372] 2020/01/10 15:17:49.637613 [TRC] 172.18.206.186:7422 - lid:1 - <<- [PONG]
c1          | [1372] 2020/01/10 15:17:49.732680 [DBG] 172.18.194.70:49157 - lid:1 - LeafNode Ping Timer
c1          | [1372] 2020/01/10 15:17:49.732680 [TRC] 172.18.194.70:49157 - lid:1 - ->> [PING]
c2          | [1372] 2020/01/10 15:17:49.717524 [TRC] 172.18.206.186:7422 - lid:1 - <<- [PING]
c2          | [1372] 2020/01/10 15:17:49.717524 [TRC] 172.18.206.186:7422 - lid:1 - ->> [PONG]
c1          | [1372] 2020/01/10 15:17:49.732680 [TRC] 172.18.194.70:49157 - lid:1 - <<- [PONG]
c1          | [1372] 2020/01/10 15:17:51.714580 [DBG] 10.35.68.24:62849 - cid:2 - Client Ping Timer
c1          | [1372] 2020/01/10 15:17:51.714580 [TRC] 10.35.68.24:62849 - cid:2 - ->> [PING]
c1          | [1372] 2020/01/10 15:17:51.714580 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PONG]
c1          | [1372] 2020/01/10 15:18:00.301474 [DBG] 10.35.68.24:62850 - cid:3 - Client connection created
c1          | [1372] 2020/01/10 15:18:00.302611 [TRC] 10.35.68.24:62850 - cid:3 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"a","pass":"[REDACTED]","tls_required":false,"name":"NATS Sample Requestor","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62850 - cid:3 - <<- [PING]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62850 - cid:3 - ->> [PONG]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62850 - cid:3 - <<- [SUB _INBOX.W7P0kJjrbQVrbmzAqqk6V1.*  1]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62850 - cid:3 - <<- [PUB test.service.1 _INBOX.W7P0kJjrbQVrbmzAqqk6V1.9cn7513D 3]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62850 - cid:3 - <<- MSG_PAYLOAD: ["foo"]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62849 - cid:2 - ->> [PING]
c1          | [1372] 2020/01/10 15:18:00.302866 [TRC] 10.35.68.24:62849 - cid:2 - ->> [MSG test.service.1 1 _INBOX.W7P0kJjrbQVrbmzAqqk6V1.9cn7513D 3]
c1          | [1372] 2020/01/10 15:18:00.303903 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PONG]
c1          | [1372] 2020/01/10 15:18:00.304384 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PUB _INBOX.W7P0kJjrbQVrbmzAqqk6V1.9cn7513D 13]
c1          | [1372] 2020/01/10 15:18:00.304384 [TRC] 10.35.68.24:62849 - cid:2 - <<- MSG_PAYLOAD: ["response text"]
c1          | [1372] 2020/01/10 15:18:00.304384 [TRC] 10.35.68.24:62850 - cid:3 - ->> [MSG _INBOX.W7P0kJjrbQVrbmzAqqk6V1.9cn7513D 1 13]
c1          | [1372] 2020/01/10 15:18:00.305527 [DBG] 10.35.68.24:62850 - cid:3 - Client connection closed
c1          | [1372] 2020/01/10 15:18:00.307546 [TRC] 10.35.68.24:62850 - cid:3 - <-> [DELSUB 1]
c1          | [1372] 2020/01/10 15:18:03.175280 [DBG] 10.35.68.24:62865 - cid:4 - Client connection created
c1          | [1372] 2020/01/10 15:18:03.176364 [TRC] 10.35.68.24:62865 - cid:4 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"b","pass":"[REDACTED]","tls_required":false,"name":"NATS Sample Requestor","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
c1          | [1372] 2020/01/10 15:18:03.176364 [TRC] 10.35.68.24:62865 - cid:4 - <<- [PING]
c1          | [1372] 2020/01/10 15:18:03.176364 [TRC] 10.35.68.24:62865 - cid:4 - ->> [PONG]
c1          | [1372] 2020/01/10 15:18:03.176364 [TRC] 10.35.68.24:62865 - cid:4 - <<- [SUB _INBOX.4ynIPqChOQMSroNEZqndLx.*  1]
c1          | [1372] 2020/01/10 15:18:03.177312 [TRC] 172.18.194.70:49157 - lid:1 - ->> [LS+ _INBOX.4ynIPqChOQMSroNEZqndLx.*]
c1          | [1372] 2020/01/10 15:18:03.177312 [TRC] 10.35.68.24:62865 - cid:4 - <<- [PUB test.service.1 _INBOX.4ynIPqChOQMSroNEZqndLx.HhaycK1D 3]
c1          | [1372] 2020/01/10 15:18:03.177312 [TRC] 10.35.68.24:62865 - cid:4 - <<- MSG_PAYLOAD: ["foo"]
c1          | [1372] 2020/01/10 15:18:03.177312 [TRC] 10.35.68.24:62849 - cid:2 - ->> [MSG test.service.1 1 _R_.ie4QZJ.5bq99K 3]
c2          | [1372] 2020/01/10 15:18:03.177521 [TRC] 172.18.206.186:7422 - lid:1 - <<- [LS+ _INBOX.4ynIPqChOQMSroNEZqndLx.*]
c1          | [1372] 2020/01/10 15:18:03.178465 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PUB _R_.ie4QZJ.5bq99K 13]
c1          | [1372] 2020/01/10 15:18:03.178465 [TRC] 10.35.68.24:62849 - cid:2 - <<- MSG_PAYLOAD: ["response text"]
c1          | [1372] 2020/01/10 15:18:03.178530 [TRC] 10.35.68.24:62865 - cid:4 - ->> [MSG _INBOX.4ynIPqChOQMSroNEZqndLx.HhaycK1D 1 13]
c1          | [1372] 2020/01/10 15:18:03.179615 [DBG] 10.35.68.24:62865 - cid:4 - Client connection closed
c1          | [1372] 2020/01/10 15:18:03.180602 [TRC] 10.35.68.24:62865 - cid:4 - <-> [DELSUB 1]
c1          | [1372] 2020/01/10 15:18:03.180602 [TRC] 172.18.194.70:49157 - lid:1 - ->> [LS- _INBOX.4ynIPqChOQMSroNEZqndLx.*]
c2          | [1372] 2020/01/10 15:18:03.179385 [TRC] 172.18.206.186:7422 - lid:1 - <<- [LS- _INBOX.4ynIPqChOQMSroNEZqndLx.*]
c2          | [1372] 2020/01/10 15:18:03.181119 [TRC] 172.18.206.186:7422 - lid:1 - <-> [DELSUB _INBOX.4ynIPqChOQMSroNEZqndLx.*]
c2          | [1372] 2020/01/10 15:18:05.761225 [DBG] 10.35.68.24:62866 - cid:2 - Client connection created
c2          | [1372] 2020/01/10 15:18:05.762291 [TRC] 10.35.68.24:62866 - cid:2 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"c","pass":"[REDACTED]","tls_required":false,"name":"NATS Sample Requestor","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 10.35.68.24:62866 - cid:2 - <<- [PING]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 10.35.68.24:62866 - cid:2 - ->> [PONG]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 10.35.68.24:62866 - cid:2 - <<- [SUB _INBOX.TfzSpQyvrMigTw0TP7cMHt.*  1]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 172.18.206.186:7422 - lid:1 - ->> [LS+ _INBOX.TfzSpQyvrMigTw0TP7cMHt.*]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 10.35.68.24:62866 - cid:2 - <<- [PUB test.service.1 _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 3]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 10.35.68.24:62866 - cid:2 - <<- MSG_PAYLOAD: ["foo"]
c2          | [1372] 2020/01/10 15:18:05.762524 [TRC] 172.18.206.186:7422 - lid:1 - ->> [LMSG test.service.1 _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 3]
c1          | [1372] 2020/01/10 15:18:05.763695 [TRC] 172.18.194.70:49157 - lid:1 - <<- [LS+ _INBOX.TfzSpQyvrMigTw0TP7cMHt.*]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 172.18.194.70:49157 - lid:1 - <<- [LMSG test.service.1 _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 3]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 172.18.194.70:49157 - lid:1 - <<- MSG_PAYLOAD: ["foo"]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 10.35.68.24:62849 - cid:2 - ->> [MSG test.service.1 1 _R_.ie4QZJ.x9JGBo 3]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PUB _R_.ie4QZJ.x9JGBo 13]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 10.35.68.24:62849 - cid:2 - <<- MSG_PAYLOAD: ["response text"]
c1          | [1372] 2020/01/10 15:18:05.763912 [TRC] 172.18.194.70:49157 - lid:1 - ->> [LMSG _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 13]
c2          | [1372] 2020/01/10 15:18:05.764649 [TRC] 172.18.206.186:7422 - lid:1 - <<- [LMSG _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 13]
c2          | [1372] 2020/01/10 15:18:05.764649 [TRC] 172.18.206.186:7422 - lid:1 - <<- MSG_PAYLOAD: ["response text"]
c2          | [1372] 2020/01/10 15:18:05.765070 [TRC] 10.35.68.24:62866 - cid:2 - ->> [MSG _INBOX.TfzSpQyvrMigTw0TP7cMHt.05sUrsio 1 13]
c2          | [1372] 2020/01/10 15:18:05.766173 [DBG] 10.35.68.24:62866 - cid:2 - Client connection closed
c2          | [1372] 2020/01/10 15:18:05.766411 [TRC] 10.35.68.24:62866 - cid:2 - <-> [DELSUB 1]
c2          | [1372] 2020/01/10 15:18:05.766411 [TRC] 172.18.206.186:7422 - lid:1 - ->> [LS- _INBOX.TfzSpQyvrMigTw0TP7cMHt.*]
c1          | [1372] 2020/01/10 15:18:05.766060 [TRC] 172.18.194.70:49157 - lid:1 - <<- [LS- _INBOX.TfzSpQyvrMigTw0TP7cMHt.*]
c1          | [1372] 2020/01/10 15:18:05.766060 [TRC] 172.18.194.70:49157 - lid:1 - <-> [DELSUB _INBOX.TfzSpQyvrMigTw0TP7cMHt.*]
c2          | [1372] 2020/01/10 15:18:07.378670 [DBG] 10.35.68.24:62867 - cid:3 - Client connection created
c2          | [1372] 2020/01/10 15:18:07.378670 [TRC] 10.35.68.24:62867 - cid:3 - <<- [CONNECT {"verbose":false,"pedantic":false,"user":"d","pass":"[REDACTED]","tls_required":false,"name":"NATS Sample Requestor","lang":"go","version":"1.9.1","protocol":1,"echo":true}]
c2          | [1372] 2020/01/10 15:18:07.378670 [TRC] 10.35.68.24:62867 - cid:3 - <<- [PING]
c2          | [1372] 2020/01/10 15:18:07.379670 [TRC] 10.35.68.24:62867 - cid:3 - ->> [PONG]
c2          | [1372] 2020/01/10 15:18:07.379746 [TRC] 10.35.68.24:62867 - cid:3 - <<- [SUB _INBOX.89dvNgB1mAb4aZo4PLaWJz.*  1]
c2          | [1372] 2020/01/10 15:18:07.380243 [TRC] 10.35.68.24:62867 - cid:3 - <<- [PUB test.service.1 _INBOX.89dvNgB1mAb4aZo4PLaWJz.WyXS3UnR 3]
c2          | [1372] 2020/01/10 15:18:07.380243 [TRC] 10.35.68.24:62867 - cid:3 - <<- MSG_PAYLOAD: ["foo"]
c2          | [1372] 2020/01/10 15:18:07.380243 [TRC] 172.18.206.186:7422 - lid:1 - ->> [LMSG test.service.1 _R_.BBa91r.hQOCWj 3]
c1          | [1372] 2020/01/10 15:18:07.380535 [TRC] 172.18.194.70:49157 - lid:1 - <<- [LMSG test.service.1 _R_.BBa91r.hQOCWj 3]
c1          | [1372] 2020/01/10 15:18:07.380535 [TRC] 172.18.194.70:49157 - lid:1 - <<- MSG_PAYLOAD: ["foo"]
c1          | [1372] 2020/01/10 15:18:07.380747 [TRC] 10.35.68.24:62849 - cid:2 - ->> [MSG test.service.1 1 _R_.ie4QZJ.tVfoKl 3]
c1          | [1372] 2020/01/10 15:18:07.380747 [TRC] 10.35.68.24:62849 - cid:2 - <<- [PUB _R_.ie4QZJ.tVfoKl 13]
c1          | [1372] 2020/01/10 15:18:07.380747 [TRC] 10.35.68.24:62849 - cid:2 - <<- MSG_PAYLOAD: ["response text"]
c2          | [1372] 2020/01/10 15:18:09.386622 [DBG] 10.35.68.24:62867 - cid:3 - Client connection closed
c2          | [1372] 2020/01/10 15:18:09.386891 [TRC] 10.35.68.24:62867 - cid:3 - <-> [DELSUB 1]
Gracefully stopping... (press Ctrl+C again to force)
Stopping c2   ... done
Stopping c1   ... done

Versions of nats-server and affected client libraries used:

See logs. The go examples are as of commit f66f9c02346dc33296576bf0ef4bd48520bf88c9.

OS/Container environment:

Windows nanoserver

Steps or code to reproduce the issue:

docker-compose.yml

version: "3.2"

services:
 cluster1: 
   image: nats:2.1.2-nanoserver
   container_name: c1
   command: -c C:\\mount\\c1 -DV
   ports: 
     - 80:8222
     - 4244:4244
   expose:
     - "7422"
   volumes:
     - .\:C:\mount\
   networks:
     - cluster1
   restart: always
 cluster2: 
   depends_on: 
     - cluster1
   image: nats:2.1.2-nanoserver
   container_name: c2
   command: -c C:\\mount\\c2 -DV
   ports: 
     - 81:8222
     - 4245:4244
   expose:
     - "7422"
   volumes:
     - .\:C:\mount\
   networks:
     - cluster1
   restart: always
 
networks:
 cluster1:

cluster 1 config:

port: 4244
monitor_port: 8222
accounts: {
  A: {
    users:[{
      user: a
      password: a
    }]
    exports: [
      {service: test.service.>}
    ]
  },
  B: {
    users:[{
       user: b
        password: b
    }]
    imports: [
      {service: {account: A, subject: test.service.1}}
    ]
  }
}

leafnodes {
  port: 7422
  authorization {
    account: B
  }
}

cluster 2 config:

port: 4244
monitor_port: 8222
accounts: {
  C: {
    users:[{
      user: c
      password: c
    }]
    exports: [
      {service: test.service.>}
    ]
  },
  D: {
    users:[{
       user: d
       password: d
    }]
    imports: [
      {service: {account: C, subject: test.service.1}}
    ]
  }
}
leafnodes {
  remotes: [
    {
      urls: [
        nats-leaf://c1:7422
      ]
      account: C
    }
  ]
}

Starting a nats-rply: start "cluster1 Account A service" nats-rply -s nats://a:a@localhost:4244 test.service.1 "response text"

Sending request to account D: nats-req -s nats://d:d@localhost:4245 test.service.1 foo

Expected result:

Request is sent from account D on cluster 2 to service listening at test.service.1 on Account A on cluster 1, and the requester gets “response text” back.

Actual result:

The service listening at test.service.1 gets a request of ‘foo’, but no message is returned to requester. Instead: “nats: timeout for request”

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Comments: 41 (22 by maintainers)

Most upvoted comments

@derekcollison I’ll get back to you by Tuesday.

+1
cjmang on Apr 11, 2020
Read more comments on GitHub
← nats-server: Round-robin load balance fairness with slow queue subscribers
nats-server: subscription count in subsz is wrong →