NATS server disconnecting randomly #620

knvpk · 2019-11-16T06:55:28Z

Prerequisites

Please answer the following questions for yourself before submitting an issue.

I am running the 0.13.11 version
I checked the documentation and found no answer
I checked to make sure that this issue has not already been filed
I'm reporting the issue to the correct repository (May be it belongs to NATS repository I don't know)

Current Behavior

Im using the transporter NATS option by keeping the config as transporter: "NATS", But while coding in vscode and hotreloading sometimes NATS server is disconnecting and saying the error as Invalid subject, but again changing the some code and hot reloading it is reconnecting successfully. Actually this can be ok in development , but we are using docker deployment there is no option for hot-reloading option so that NATS can reconnect again.

Expected Behavior

While coding and hot reloading the NATS server should stay connected always.

Failure Information

Please check the image for more error info

Steps to Reproduce

Please provide detailed steps for reproducing the issue.

init project with moleculer cli
added 2 or more services
Use NATS as transporter
Try to change code and do hot-reloads

Context

Please provide any relevant information about your setup. This is important in case the issue is not reproducible except for under certain conditions.

Moleculer version:0.13.11
NodeJS version: 8.12.0
Operating System: Ubuntu 19.04

The text was updated successfully, but these errors were encountered:

icebob · 2019-11-16T11:08:12Z

Are you using NATS client with pedantic option?

knvpk · 2019-11-16T12:00:34Z

No, im not giving any external options for NATS server
I installed the nats server from this page https://github.com/nats-io/nats-server/releases/tag/v2.1.0 and in Assets using amd64.deb file and every time i just issue nats-server command. the out put will be like

[27788] 2019/11/16 17:29:04.823411 [INF] Starting nats-server version 2.1.0
[27788] 2019/11/16 17:29:04.823472 [INF] Git commit [1cc5ae0]
[27788] 2019/11/16 17:29:04.823790 [INF] Listening for client connections on 0.0.0.0:4222
[27788] 2019/11/16 17:29:04.823804 [INF] Server id is ND3MCWQTI4FG5PGKZD2M47OW5XRTMDGYJS736HJTMHZ6RBRIKB7QO6BR
[27788] 2019/11/16 17:29:04.823814 [INF] Server is ready

And in docker-compose.yml i use the nats docker image as below

  nats:
    image: nats:latest
    ports:
      - "4222:4222"

knvpk · 2019-11-16T12:24:36Z

For more info:
I just kept log level to debug in moleculerjs config then i got this out put

[2019-11-16T12:22:17.331Z] DEBUG 088922e1243d-19/TRANSPORTER: { NatsError: 'Invalid Subject'
at Client.processErr (/app/node_modules/nats/lib/nats.js:1389:28)
at Client.processInbound (/app/node_modules/nats/lib/nats.js:1118:30)
at Socket.stream.on (/app/node_modules/nats/lib/nats.js:738:14)
at Socket.emit (events.js:198:13)
at addChunk (_stream_readable.js:287:12)
at readableAddChunk (_stream_readable.js:268:11)
at Socket.Readable.push (_stream_readable.js:223:10)
 at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17) name: 'NatsError', message: '\'Invalid Subject\'', code: 'NATS_PROTOCOL_ERR', chainedError: undefined }

icebob · 2019-11-16T12:34:03Z

It's weird. I've checked the source code of NATS and it seems it throws this error if pedantic is enabled and some client publish a topic which has no subscriber.

knvpk · 2019-11-16T12:49:31Z

May be pendantic is enabled by default, can you tell me how to disable that.

icebob · 2019-11-16T13:02:49Z

try it in moleculer.config.js

module.exports = {
    transporter: {
        type: "NATS",
        options: {
            url: "nats://localhost:4222",
            pedantic: false
        }
    }
}

knvpk · 2019-11-17T03:59:10Z

@icebob , I checked with that configuration, but still error is coming.

[2019-11-17T03:57:33.036Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:33.068Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:35.071Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:35.074Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:37.075Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:37.078Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:39.079Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:39.084Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:41.087Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:41.090Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:43.092Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:43.096Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:45.098Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:45.101Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
[2019-11-17T03:57:47.104Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...
[2019-11-17T03:57:47.107Z] ERROR mylaptop-6560/TRANSPORTER: NATS error. 'Invalid Subject'
^C[2019-11-17T03:57:49.108Z] WARN  mylaptop-6560/TRANSPORTER: NATS client is reconnecting...

knvpk · 2019-11-17T04:01:16Z

These are the logs from NATS server side

[6625] 2019/11/17 09:29:44.532738 [INF] Starting nats-server version 2.0.0
[6625] 2019/11/17 09:29:44.532833 [DBG] Go build version go1.11.10
[6625] 2019/11/17 09:29:44.532852 [INF] Git commit [not set]
[6625] 2019/11/17 09:29:44.533065 [INF] Listening for client connections on 0.0.0.0:4222
[6625] 2019/11/17 09:29:44.533083 [INF] Server id is NBWAVSBAJEQRATEJYY6HPGD5LU3WGMSGIBDPWQLETTL2S7NSYUQ6YYQF
[6625] 2019/11/17 09:29:44.533094 [INF] Server is ready
[6625] 2019/11/17 09:29:44.533109 [DBG] Get non local IPs for "0.0.0.0"
[6625] 2019/11/17 09:29:44.533739 [DBG]  ip=192.168.0.109
[6625] 2019/11/17 09:29:44.533834 [DBG]  ip=172.18.0.1
[6625] 2019/11/17 09:29:44.533922 [DBG]  ip=172.19.0.1
[6625] 2019/11/17 09:29:44.534013 [DBG]  ip=172.17.0.1
[6625] 2019/11/17 09:29:49.789085 [DBG] 127.0.0.1:46532 - cid:1 - Client connection created
[6625] 2019/11/17 09:29:53.158434 [DBG] 127.0.0.1:46532 - cid:1 - Client connection closed
[6625] 2019/11/17 09:29:55.162385 [DBG] 127.0.0.1:46560 - cid:2 - Client connection created
[6625] 2019/11/17 09:29:55.165186 [DBG] 127.0.0.1:46560 - cid:2 - Client connection closed
[6625] 2019/11/17 09:29:57.167634 [DBG] 127.0.0.1:46562 - cid:3 - Client connection created
[6625] 2019/11/17 09:29:57.169971 [DBG] 127.0.0.1:46562 - cid:3 - Error flushing: writev tcp 127.0.0.1:4222->127.0.0.1:46562: writev: connection reset by peer
[6625] 2019/11/17 09:29:57.170014 [DBG] 127.0.0.1:46562 - cid:3 - Client connection closed
[6625] 2019/11/17 09:29:59.173343 [DBG] 127.0.0.1:46564 - cid:4 - Client connection created
[6625] 2019/11/17 09:29:59.175506 [DBG] 127.0.0.1:46564 - cid:4 - Error flushing: writev tcp 127.0.0.1:4222->127.0.0.1:46564: writev: connection reset by peer
[6625] 2019/11/17 09:29:59.175677 [DBG] 127.0.0.1:46564 - cid:4 - Client connection closed
[6625] 2019/11/17 09:30:01.179409 [DBG] 127.0.0.1:46566 - cid:5 - Client connection created
[6625] 2019/11/17 09:30:01.181779 [DBG] 127.0.0.1:46566 - cid:5 - Client connection closed
[6625] 2019/11/17 09:30:03.184111 [DBG] 127.0.0.1:46568 - cid:6 - Client connection created
[6625] 2019/11/17 09:30:03.186558 [DBG] 127.0.0.1:46568 - cid:6 - Error flushing: writev tcp 127.0.0.1:4222->127.0.0.1:46568: writev: connection reset by peer

icebob · 2019-11-17T08:04:33Z

Thanks, please try it with the latest NATS server 2.1.0, as well.

knvpk · 2019-11-18T04:25:20Z

Same error with NATS 2.1.0 also

[3326] 2019/11/18 09:52:06.771147 [INF] Starting nats-server version 2.1.0
[3326] 2019/11/18 09:52:06.771274 [DBG] Go build version go1.12.9
[3326] 2019/11/18 09:52:06.771284 [INF] Git commit [1cc5ae0]
[3326] 2019/11/18 09:52:06.771685 [INF] Listening for client connections on 0.0.0.0:4222
[3326] 2019/11/18 09:52:06.771705 [INF] Server id is NAGSPDMONL73TIUQIZLL7U547B5DPZOKBAFZTSZRE5AQA5LOFMRJYOV6
[3326] 2019/11/18 09:52:06.771714 [INF] Server is ready
[3326] 2019/11/18 09:52:06.771727 [DBG] Get non local IPs for "0.0.0.0"
[3326] 2019/11/18 09:52:06.772267 [DBG]  ip=192.168.0.12
[3326] 2019/11/18 09:52:06.772355 [DBG]  ip=172.18.0.1
[3326] 2019/11/18 09:52:06.772432 [DBG]  ip=172.19.0.1
[3326] 2019/11/18 09:52:06.772508 [DBG]  ip=172.17.0.1
[3326] 2019/11/18 09:54:32.510493 [DBG] 127.0.0.1:43568 - cid:1 - Client connection created
[3326] 2019/11/18 09:54:39.520810 [DBG] 127.0.0.1:43568 - cid:1 - Client connection closed
[3326] 2019/11/18 09:54:41.524456 [DBG] 127.0.0.1:43598 - cid:2 - Client connection created
[3326] 2019/11/18 09:54:41.527204 [DBG] 127.0.0.1:43598 - cid:2 - Client connection closed
[3326] 2019/11/18 09:54:43.529903 [DBG] 127.0.0.1:43600 - cid:3 - Client connection created
[3326] 2019/11/18 09:54:43.532129 [DBG] 127.0.0.1:43600 - cid:3 - Error flushing: writev tcp 127.0.0.1:4222->127.0.0.1:43600: writev: connection reset by peer
[3326] 2019/11/18 09:54:43.532265 [DBG] 127.0.0.1:43600 - cid:3 - Client connection closed
[3326] 2019/11/18 09:54:45.533725 [DBG] 127.0.0.1:43602 - cid:4 - Client connection created
[3326] 2019/11/18 09:54:45.535888 [DBG] 127.0.0.1:43602 - cid:4 - Client connection closed
[3326] 2019/11/18 09:54:47.539372 [DBG] 127.0.0.1:43604 - cid:5 - Client connection created
[3326] 2019/11/18 09:54:47.541674 [DBG] 127.0.0.1:43604 - cid:5 - Client connection closed
[3326] 2019/11/18 09:54:49.544227 [DBG] 127.0.0.1:43610 - cid:6 - Client connection created
[3326] 2019/11/18 09:54:49.546708 [DBG] 127.0.0.1:43610 - cid:6 - Client connection closed

icebob · 2019-11-19T17:52:20Z

But it happens when you hotreload a service, right?

knvpk · 2019-11-20T04:55:13Z

I will tell you clearly

When ever i start the project using npm run dev, after all services loaded these errors are coming, then i will go to one of the service file any_one_of.service.ts file click save, then it will hot reload and reconnect.... Also randomly it disconnects again then again i need to click save for any one of the service file so it reconnects

icebob · 2019-11-20T16:01:15Z

very very strange. Could you make a video about it? :)

knvpk · 2019-12-12T13:20:46Z

Hi @icebob , I have sent you mail with screen recording video please check once.

knvpk · 2019-12-14T07:22:19Z

Hi @icebob , Debugging in depth i found the actual line of code which is causing this problem i think it will help to find out actual error.

We are actually using the your kantab project config mixin along with config service, in that config mixin if we comment the events line then this problem is not coming.

icebob · 2019-12-15T10:15:02Z

Hmm, it means, the event name contains some prohibited character. Could you print out the events object to the console. to see the event names?

knvpk · 2019-12-16T05:05:18Z

These are the possible event names form different services

From accounts service:

{
  'config.site.**.changed': [Function: eventHandler],
  'config.mail.**.changed': [Function: eventHandler],
  'config.accounts.**.changed': [Function: eventHandler]
}

From mail service:

{
  'config.site.**.changed': [Function: eventHandler],
  'config.mail.**.changed': [Function: eventHandler]
}

These accounts and mails service is from your repository only.

icebob · 2019-12-16T17:32:17Z

I have no idea. Could you create a small reproduce repo?

icebob · 2019-12-16T17:39:40Z

Not need it. I can reproduce.

…disabled

Fixes #630 + Backport fix #620

icebob · 2019-12-17T20:08:38Z

Released in 0.13.12

roonie007 · 2019-12-27T00:11:29Z

@icebob is this fix available in 0.14.0 ?

knvpk · 2019-12-27T12:38:23Z

Hi @icebob , i installed 0.13.12 and it working fine now.

AndreMaz · 2019-12-27T16:38:32Z

@roonie007 it's not available it latest beta 0.14.0-beta6. But you can use it by installing directly from github (next branch) with npm i moleculerjs/moleculer

icebob · 2020-01-09T20:04:39Z

Released in 0.14.0-beta7

knvpk changed the title ~~NATS server disconnected randomly~~ NATS server disconnecting randomly Nov 16, 2019

icebob added Module: Transporter Status: Need reproduce Issue waits for reproducing labels Nov 17, 2019

icebob added a commit that referenced this issue Dec 16, 2019

Fix #620 - register NATS friendly wildchar event names when balancer …

84a8b6b

…disabled

AndreMaz mentioned this issue Dec 16, 2019

Fix makeBalancedSubscriptions #632

Merged

1 task

AndreMaz added a commit to AndreMaz/moleculer that referenced this issue Dec 17, 2019

Backport fix moleculerjs#620

411067c

AndreMaz mentioned this issue Dec 17, 2019

Fixes #630 + Backport fix #620 #633

Merged

6 tasks

AndreMaz closed this as completed in #633 Dec 17, 2019

AndreMaz added a commit that referenced this issue Dec 17, 2019

Merge pull request #633 from AndreMaz/master

aa9afcf

Fixes #630 + Backport fix #620

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NATS server disconnecting randomly #620

NATS server disconnecting randomly #620

knvpk commented Nov 16, 2019

icebob commented Nov 16, 2019

knvpk commented Nov 16, 2019

knvpk commented Nov 16, 2019

icebob commented Nov 16, 2019

knvpk commented Nov 16, 2019

icebob commented Nov 16, 2019

knvpk commented Nov 17, 2019

knvpk commented Nov 17, 2019

icebob commented Nov 17, 2019

knvpk commented Nov 18, 2019

icebob commented Nov 19, 2019

knvpk commented Nov 20, 2019

icebob commented Nov 20, 2019

knvpk commented Dec 12, 2019

knvpk commented Dec 14, 2019

icebob commented Dec 15, 2019

knvpk commented Dec 16, 2019

icebob commented Dec 16, 2019

icebob commented Dec 16, 2019

icebob commented Dec 17, 2019

roonie007 commented Dec 27, 2019

knvpk commented Dec 27, 2019

AndreMaz commented Dec 27, 2019 •

edited by icebob

icebob commented Jan 9, 2020

NATS server disconnecting randomly #620

NATS server disconnecting randomly #620

Comments

knvpk commented Nov 16, 2019

Prerequisites

Current Behavior

Expected Behavior

Failure Information

Steps to Reproduce

Context

icebob commented Nov 16, 2019

knvpk commented Nov 16, 2019

knvpk commented Nov 16, 2019

icebob commented Nov 16, 2019

knvpk commented Nov 16, 2019

icebob commented Nov 16, 2019

knvpk commented Nov 17, 2019

knvpk commented Nov 17, 2019

icebob commented Nov 17, 2019

knvpk commented Nov 18, 2019

icebob commented Nov 19, 2019

knvpk commented Nov 20, 2019

icebob commented Nov 20, 2019

knvpk commented Dec 12, 2019

knvpk commented Dec 14, 2019

icebob commented Dec 15, 2019

knvpk commented Dec 16, 2019

icebob commented Dec 16, 2019

icebob commented Dec 16, 2019

icebob commented Dec 17, 2019

roonie007 commented Dec 27, 2019

knvpk commented Dec 27, 2019

AndreMaz commented Dec 27, 2019 • edited by icebob

icebob commented Jan 9, 2020

AndreMaz commented Dec 27, 2019 •

edited by icebob