Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NATS cluster: tons of Error reading from client: invalid character '"' after top-level value #270

Closed
awdrius opened this issue May 11, 2016 · 25 comments
Assignees

Comments

@awdrius
Copy link

awdrius commented May 11, 2016

Hello, I'm trying to start introducing NATS as a microservice communication protocol on mesos. I'm using mesos master nodes as seed nodes for NATS and each mesos slave runs gnatsd pointing to those seed nodes. I observed a peculiar flood of messages once I start/restart a bunch of mesos slaves (and gnatsd as it runs on those slaves).

This is small extract from gnats log:

[7723] 2016/05/11 16:42:37.015681 [ERR] 10.21.0.31:7222 - rid:96441 - Route Error {"server_id":"OWN6ITRHRzycwYnuZVpESI","version":"0.8.0","go":"","host":"10.21.0.9","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.9:7222/"}Parser Error'
[7723] 2016/05/11 16:42:37.016299 [ERR] 10.21.0.20:48898 - rid:96291 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.017219 [ERR] 10.21.0.3:7222 - rid:96502 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.018002 [ERR] 10.21.0.11:7222 - rid:91454 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.018738 [ERR] 10.21.0.30:35941 - rid:96520 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.021777 [ERR] 10.21.0.25:23365 - rid:96456 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.022236 [ERR] 10.21.0.34:28619 - rid:96325 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.025008 [ERR] 10.21.0.20:7222 - rid:96523 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.026082 [ERR] 10.21.0.25:7222 - rid:96535 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.027167 [ERR] 10.21.0.11:3391 - rid:96527 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.028311 [ERR] 10.21.0.14:56649 - rid:96437 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.028988 [ERR] 10.21.0.3:57138 - rid:96524 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.029456 [ERR] 10.21.0.31:7222 - rid:96522 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.035386 [ERR] 10.21.0.4:7222 - rid:96442 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.055451 [ERR] 10.21.0.37:3716 - rid:96492 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.057689 [ERR] 10.21.0.3:7222 - rid:96543 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.075498 [ERR] 10.21.0.33:7222 - rid:96436 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.407565 [ERR] 10.21.0.20:7222 - rid:96540 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.411138 [ERR] 10.21.0.17:29337 - rid:96486 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.413138 [ERR] 10.21.0.22:65103 - rid:96241 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.413265 [ERR] 10.21.0.34:28632 - rid:96539 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.424351 [ERR] 10.21.0.38:50446 - rid:96334 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.431253 [ERR] 10.21.0.19:35303 - rid:96376 - Route Error 'Parser Error'
[7723] 2016/05/11 16:42:37.458023 [ERR] 10.21.0.15:38285 - rid:96521 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.470157 [ERR] 10.21.0.37:3758 - rid:96564 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.471790 [ERR] 10.21.0.9:13872 - rid:96479 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.496984 [ERR] 10.21.0.20:7222 - rid:96624 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.497997 [ERR] 10.21.0.9:15451 - rid:96669 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.500422 [ERR] 10.21.0.12:7863 - rid:96530 - Route Error {"server_id":"OWN6ITRHRzycwYnuZVpESI","version":"0.8.0","go":"","host":"10.21.0.9","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.9:7222/"}Parser Error'
[7723] 2016/05/11 16:42:37.527624 [ERR] 10.21.0.16:57330 - rid:96500 - Error reading from client: invalid character '"' after top-level value
[7723] 2016/05/11 16:42:37.572838 [ERR] 10.21.0.18:14535 - rid:96519 - Route Error 'Parser Error'

I tried using -DV flag for more info but I could not find anything related so I decided not to include it here as it's super verbose.

As a side effect noticed that sometimes (rarely) some of the gnatsd on mesos slaves keep running but are not connected to the rest of the cluster. Another case is when I restart gnatsd on one of the slave and it produces a cascading flood of logs like above. While observing /routez monitoring endpoint I can see "num_rutes" going up and down as if propagating routes cycles other live gnatsd instances.

Configuration files for seed nodes (routes changes depending on server):

port: 4222
http_port: 8222

cluster {
  host: '10.21.0.2'
  port: 7222

  routes = [
    nats-route://mesos-master-2:7222
    nats-route://mesos-master-3:7222
  ]
}

Configuration for slave nodes:

port: 4222

cluster {
  host: '10.21.0.30' # Managed by startup script
  port: 7222

  routes = [
    nats-route://mesos-master-1:7222
    nats-route://mesos-master-2:7222
    nats-route://mesos-master-3:7222
  ]
}

I'm not certain if there is something wrong with the configuration files or my idea to run gnatsd on each mesos slave (for mesh cluster) is not the best use case for NATS.

If you need more details - let me know. I can alter configuration and deploy test code if needed.

@kozlovic
Copy link
Member

Quick question: are all your servers of the same version?

@awdrius
Copy link
Author

awdrius commented May 11, 2016

@kozlovic Yes, they're all on the same gnatsd 0.8.0 version.

@derekcollison
Copy link
Member

Although verbose, we may be able to use the -DV log information could be helpful to the NATS team. I believe something other than a route connection is connection to the route port.

@kozlovic
Copy link
Member

kozlovic commented May 11, 2016

Have you the log from 10.21.0.31 by any chance?

[7723] 2016/05/11 16:42:37.015681 [ERR] 10.21.0.31:7222 - rid:96441 - Route Error {"server_id":"OWN6ITRHRzycwYnuZVpESI","version":"0.8.0","go":"","host":"10.21.0.9","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.9:7222/"}Parser Error'

Also, the error says that it gets an INFO from 10.21.0.9, any idea what is running on that host?

@awdrius
Copy link
Author

awdrius commented May 11, 2016

@derekcollison No problem. Do you know a good place to place logs so that I would not pollute this thread?

@awdrius
Copy link
Author

awdrius commented May 11, 2016

@kozlovic I have them:

Start 10.21.0.31:

[825] 2016/05/11 16:42:07.266892 [INF] Starting nats-server version 0.8.0
[825] 2016/05/11 16:42:07.266980 [INF] Listening for route connections on 10.21.0.31:7222
[825] 2016/05/11 16:42:07.267068 [INF] Listening for client connections on 0.0.0.0:4222
[825] 2016/05/11 16:42:07.267107 [INF] Server is ready
[825] 2016/05/11 16:42:07.273272 [ERR] 10.21.0.16:18598 - rid:6 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.274221 [ERR] 10.21.0.37:54777 - rid:7 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.276166 [ERR] 10.21.0.24:59077 - rid:5 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.278241 [ERR] 10.21.0.18:40404 - rid:15 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.278591 [ERR] 10.21.0.10:63776 - rid:25 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.280708 [ERR] 10.21.0.16:7222 - rid:21 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.281130 [ERR] 10.21.0.12:37587 - rid:17 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.575228 [ERR] 10.21.0.19:7222 - rid:163 - Error reading from client: invalid     character '"' after top-level value
[825] 2016/05/11 16:42:07.582954 [ERR] 10.21.0.3:7222 - rid:1 - Error reading from client: invalid        character '"' after top-level value
[825] 2016/05/11 16:42:07.586072 [ERR] 10.21.0.37:7222 - rid:23 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.586184 [ERR] 10.21.0.23:7222 - rid:164 - Route Error {"server_id":              "c1WavpAMoGOCUEVmLngLIi","version":"0.8.0","go":"","host":"10.21.0.19","port":7222,"auth_required":false, "ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10. 21.0.19:7222/"}Parser Error'
[825] 2016/05/11 16:42:07.589882 [ERR] 10.21.0.11:61213 - rid:12 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.590191 [ERR] 10.21.0.14:2264 - rid:9 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.591689 [ERR] 10.21.0.24:59078 - rid:47 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.593101 [ERR] 10.21.0.3:7222 - rid:190 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.602562 [ERR] 10.21.0.23:56800 - rid:195 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.604988 [ERR] 10.21.0.23:7222 - rid:215 - Error reading from client: invalid     character '"' after top-level value
[825] 2016/05/11 16:42:07.610009 [ERR] 10.21.0.23:7222 - rid:220 - Error reading from client: invalid     character '"' after top-level value
[825] 2016/05/11 16:42:07.610132 [ERR] 10.21.0.14:7222 - rid:200 - Error reading from client: invalid     character '"' after top-level value
[825] 2016/05/11 16:42:07.610699 [ERR] 10.21.0.37:7222 - rid:194 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.611747 [ERR] 10.21.0.2:7222 - rid:2 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.613129 [ERR] 10.21.0.11:7222 - rid:198 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.613394 [ERR] 10.21.0.12:37595 - rid:72 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.613860 [ERR] 10.21.0.9:37992 - rid:28 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.614004 [ERR] 10.21.0.4:7222 - rid:3 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.614672 [ERR] 10.21.0.25:53147 - rid:13 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.614710 [ERR] 10.21.0.3:7222 - rid:205 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.615725 [ERR] 10.21.0.24:7222 - rid:201 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.616128 [ERR] 10.21.0.2:43072 - rid:242 - Route Error 'Parser Error'
[825] 2016/05/11 16:42:07.619119 [ERR] 10.21.0.14:7222 - rid:230 - Error reading from client: invalid     character '"' after top-level value

Start of 10.21.0.9:

[827] 2016/05/11 16:38:58.583587 [INF] Starting nats-server version 0.8.0
[827] 2016/05/11 16:38:58.583860 [INF] Listening for route connections on 10.21.0.9:7222
[827] 2016/05/11 16:38:58.583986 [INF] Listening for client connections on 0.0.0.0:4222
[827] 2016/05/11 16:38:58.584031 [INF] Server is ready
[827] 2016/05/11 16:40:36.577628 [ERR] 10.21.0.18:7222 - rid:11 - Error reading from client: invalid      character '"' after top-level value
[827] 2016/05/11 16:42:06.708679 [ERR] 10.21.0.6:48910 - rid:4 - Error reading from client: invalid       character '"' after top-level value
[827] 2016/05/11 16:42:06.710426 [ERR] 10.21.0.4:33255 - rid:3 - Route Error {"server_id":                "g3nC2596EJUmiX1bVdc6ht","version":"0.8.0","go":"","host":"10.21.0.37","port":7222,"auth_required":false, "ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10. 21.0.37:7222/"}Parser Error'
[827] 2016/05/11 16:42:06.710972 [ERR] 10.21.0.2:37140 - rid:7 - Route Error {"server_id":                "g3nC2596EJUmiX1bVdc6ht","version":"0.8.0","go":"","host":"10.21.0.37","port":7222,"auth_required":false, "ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10. 21.0.37:7222/"}Parser Error'
[827] 2016/05/11 16:42:06.711062 [ERR] 10.21.0.3:7222 - rid:1 - Route Error {"server_id":                 "g3nC2596EJUmiX1bVdc6ht","version":"0.8.0","go":"","host":"10.21.0.37","port":7222,"auth_required":false, "ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10. 21.0.37:7222/"}Parser Error'
[827] 2016/05/11 16:42:07.803115 [ERR] 10.21.0.31:7222 - rid:90 - Error reading from client: invalid      character '"' after top-level value
[827] 2016/05/11 16:42:07.804890 [ERR] 10.21.0.14:7222 - rid:44 - Error reading from client: invalid      character '"' after top-level value
[827] 2016/05/11 16:42:07.823386 [ERR] 10.21.0.31:11095 - rid:150 - Error reading from client: invalid    character '"' after top-level value
[827] 2016/05/11 16:42:07.825418 [ERR] 10.21.0.12:7222 - rid:35 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.825743 [ERR] 10.21.0.17:7222 - rid:22 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.826140 [ERR] 10.21.0.4:7222 - rid:75 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.826573 [ERR] 10.21.0.24:7222 - rid:79 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.828017 [ERR] 10.21.0.14:7222 - rid:151 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.829675 [ERR] 10.21.0.19:7222 - rid:124 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.829686 [ERR] 10.21.0.2:37218 - rid:63 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.832440 [ERR] 10.21.0.37:7222 - rid:52 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.837844 [ERR] 10.21.0.4:33399 - rid:166 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.838225 [ERR] 10.21.0.3:7222 - rid:66 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.838384 [ERR] 10.21.0.25:7222 - rid:77 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.839216 [ERR] 10.21.0.2:37323 - rid:180 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.840155 [ERR] 10.21.0.16:7222 - rid:38 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.840434 [ERR] 10.21.0.24:7222 - rid:168 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.841818 [ERR] 10.21.0.18:63860 - rid:17 - Route Error 'Parser Error'
[827] 2016/05/11 16:42:07.841942 [ERR] 10.21.0.3:7222 - rid:196 - Error reading from client: invalid      character '"' after top-level value

@derekcollison
Copy link
Member

I think you could just attach the logs by dragging into the comment box.

@kozlovic
Copy link
Member

Any chance that one of the server is trying to connect to the client port 4222? Could you check all configs?
I am seeing a server reporting the "invalid character" error when one of the server connects to another server to the client port, instead of the route port. In debug, I see that the routes are recreated constantly from the server with wrong config with a "Detected duplicate remote route" error message.

@awdrius
Copy link
Author

awdrius commented May 11, 2016

@derekcollison Attached log 10.21.0.9.verbose.zip

@kozlovic The config file (second one) in my first post is what all 30 slaves are using (it's a template and the only part that's dynamic is # Managed by startup script one).

Just a random thought but looking at the verbose log could it be that because all 30 (+3 seed) instances are restarting/dropping connection for some reason and that causes data to be just partially available on the wire?

@kozlovic
Copy link
Member

Thanks for the log, would you please provide the log for 10.21.0.2?

Are you able to have a successful deploy or is it always end-up like this? If you try to bring one server at a time, do you still get this issue? Thanks!

@kozlovic
Copy link
Member

@awdrius I think I was able to reproduce the issue with "invalid character" with lots of servers (with correctly connecting to the route port). I will keep you posted. Thanks again for the report!

@awdrius
Copy link
Author

awdrius commented May 11, 2016

@kozlovic That's good news (not that it's good it happens (-. ). Let me know if you need any help.

@kozlovic
Copy link
Member

Will do. In the meantime, if you want to experiment and see if works better deploying one server at a time...

@kozlovic
Copy link
Member

@awdrius I have made some progress, so don't waste your time experimenting. I should get an update on the next step by the end of the day.

@awdrius
Copy link
Author

awdrius commented May 11, 2016

So I tried getting a similar behavior while bringing slaves online one by one and got the same thing.

I started gnatsd on all three mesos masters to act as a seed nodes. Checking /routez confirmed that they all are fine. Then I got one of slaves gnatsd process online with no issues and nor errors in any of the logs. Once I started the second gnatsd process on a second slave all three initial nodes started complaining:

master 1 (10.21.0.2):

[24765] 2016/05/11 21:29:33.755202 [INF] Starting nats-server version 0.8.0
[24765] 2016/05/11 21:29:33.755737 [INF] Starting http monitor on 0.0.0.0:8222
[24765] 2016/05/11 21:29:33.755861 [INF] Listening for route connections on 10.21.0.2:7222
[24765] 2016/05/11 21:29:33.756193 [INF] Listening for client connections on 0.0.0.0:4222
[24765] 2016/05/11 21:29:33.756220 [INF] Server is ready
[24765] 2016/05/11 21:36:28.481178 [ERR] 10.21.0.3:39347 - rid:1 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:36:28.481353 [ERR] 10.21.0.4:46756 - rid:3 - Error reading from client: invalid character '"' after top-level value 

master 2 (10.21.0.3):

[24602] 2016/05/11 21:29:44.071109 [INF] Starting nats-server version 0.8.0
[24602] 2016/05/11 21:29:44.071746 [INF] Starting http monitor on 0.0.0.0:8222
[24602] 2016/05/11 21:29:44.072095 [INF] Listening for route connections on 10.21.0.3:7222
[24602] 2016/05/11 21:29:44.072290 [INF] Listening for client connections on 0.0.0.0:4222
[24602] 2016/05/11 21:29:44.072445 [INF] Server is ready
[24602] 2016/05/11 21:36:28.481620 [ERR] 10.21.0.4:50655 - rid:3 - Error reading from client: invalid character '"' after top-level value
[24602] 2016/05/11 21:36:28.482195 [ERR] 10.21.0.2:7222 - rid:1 - Route Error {"server_id":"fVnT72z3FJHk3AwTKrrBda","version":"0.8.0","go":"","host":"10.21.0.27","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.27:7222/"}Parser Error'

master 3 (10.21.0.4):

[24694] 2016/05/11 21:29:52.892725 [INF] Starting nats-server version 0.8.0
[24694] 2016/05/11 21:29:52.893268 [INF] Starting http monitor on 0.0.0.0:8222
[24694] 2016/05/11 21:29:52.893499 [INF] Listening for route connections on 10.21.0.4:7222
[24694] 2016/05/11 21:29:52.893670 [INF] Listening for client connections on 0.0.0.0:4222
[24694] 2016/05/11 21:29:52.893821 [INF] Server is ready
[24694] 2016/05/11 21:36:28.481586 [ERR] 10.21.0.3:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[24694] 2016/05/11 21:36:28.482670 [ERR] 10.21.0.2:7222 - rid:2 - Route Error {"server_id":"fVnT72z3FJHk3AwTKrrBda","version":"0.8.0","go":"","host":"10.21.0.27","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.27:7222/"}Parser Error'

Slave 1 (in order of start) (10.21.0.27):

[11497] 2016/05/11 21:36:00.793712 [INF] Starting nats-server version 0.8.0
[11497] 2016/05/11 21:36:00.793786 [INF] Listening for route connections on 10.21.0.27:7222
[11497] 2016/05/11 21:36:00.793849 [INF] Listening for client connections on 0.0.0.0:4222
[11497] 2016/05/11 21:36:00.793880 [INF] Server is ready

Slave 2 (10.21.0.35):

[12341] 2016/05/11 21:36:28.478798 [INF] Starting nats-server version 0.8.0
[12341] 2016/05/11 21:36:28.478926 [INF] Listening for route connections on 10.21.0.35:7222
[12341] 2016/05/11 21:36:28.478996 [INF] Listening for client connections on 0.0.0.0:4222
[12341] 2016/05/11 21:36:28.479030 [INF] Server is ready

Summary: it looks like after starting second slave all seed gnatsd instances started complaining about first slave.

Out of curiosity I started gnatsd on a third slave and got the following:

master 1 (10.21.0.2):

[24765] 2016/05/11 21:29:33.755202 [INF] Starting nats-server version 0.8.0
[24765] 2016/05/11 21:29:33.755737 [INF] Starting http monitor on 0.0.0.0:8222
[24765] 2016/05/11 21:29:33.755861 [INF] Listening for route connections on 10.21.0.2:7222
[24765] 2016/05/11 21:29:33.756193 [INF] Listening for client connections on 0.0.0.0:4222
[24765] 2016/05/11 21:29:33.756220 [INF] Server is ready
[24765] 2016/05/11 21:36:28.481178 [ERR] 10.21.0.3:39347 - rid:1 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:36:28.481353 [ERR] 10.21.0.4:46756 - rid:3 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:47:38.718733 [ERR] 10.21.0.35:16890 - rid:6 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:47:38.719716 [ERR] 10.21.0.3:39484 - rid:7 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:47:38.720231 [ERR] 10.21.0.27:58279 - rid:5 - Error reading from client: invalid character '"' after top-level value
[24765] 2016/05/11 21:47:38.720289 [ERR] 10.21.0.4:46880 - rid:8 - Error reading from client: invalid character '"' after top-level value

master 2 (10.21.0.3):

[24602] 2016/05/11 21:29:44.071109 [INF] Starting nats-server version 0.8.0
[24602] 2016/05/11 21:29:44.071746 [INF] Starting http monitor on 0.0.0.0:8222
[24602] 2016/05/11 21:29:44.072095 [INF] Listening for route connections on 10.21.0.3:7222
[24602] 2016/05/11 21:29:44.072290 [INF] Listening for client connections on 0.0.0.0:4222
[24602] 2016/05/11 21:29:44.072445 [INF] Server is ready
[24602] 2016/05/11 21:36:28.481620 [ERR] 10.21.0.4:50655 - rid:3 - Error reading from client: invalid character '"' after top-level value
[24602] 2016/05/11 21:36:28.482195 [ERR] 10.21.0.2:7222 - rid:1 - Route Error {"server_id":"fVnT72z3FJHk3AwTKrrBda","version":"0.8.0","go":"","host":"10.21.0.27","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.27:7222/"}Parser Error'
[24602] 2016/05/11 21:47:38.718027 [ERR] 10.21.0.35:22859 - rid:7 - Error reading from client: invalid character '"' after top-level value
[24602] 2016/05/11 21:47:38.719066 [ERR] 10.21.0.28:14872 - rid:14 - Error reading from client: invalid character '"' after top-level value
[24602] 2016/05/11 21:47:38.720212 [ERR] 10.21.0.2:7222 - rid:9 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[24602] 2016/05/11 21:47:38.720505 [ERR] 10.21.0.27:21311 - rid:5 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[24602] 2016/05/11 21:47:38.720606 [ERR] 10.21.0.4:7222 - rid:8 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[24602] 2016/05/11 21:47:39.722032 [ERR] 10.21.0.35:7222 - rid:15 - Error reading from client: invalid character '"' after top-level value
[24602] 2016/05/11 21:47:39.725843 [ERR] 10.21.0.27:7222 - rid:19 - Error reading from client: invalid character '"' after top-level value

master 3 (10.21.0.4):

[24694] 2016/05/11 21:29:52.892725 [INF] Starting nats-server version 0.8.0
[24694] 2016/05/11 21:29:52.893268 [INF] Starting http monitor on 0.0.0.0:8222
[24694] 2016/05/11 21:29:52.893499 [INF] Listening for route connections on 10.21.0.4:7222
[24694] 2016/05/11 21:29:52.893670 [INF] Listening for client connections on 0.0.0.0:4222
[24694] 2016/05/11 21:29:52.893821 [INF] Server is ready
[24694] 2016/05/11 21:36:28.481586 [ERR] 10.21.0.3:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[24694] 2016/05/11 21:36:28.482670 [ERR] 10.21.0.2:7222 - rid:2 - Route Error {"server_id":"fVnT72z3FJHk3AwTKrrBda","version":"0.8.0","go":"","host":"10.21.0.27","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.27:7222/"}Parser Error'
[24694] 2016/05/11 21:47:38.718988 [ERR] 10.21.0.35:5827 - rid:6 - Error reading from client: invalid character '"' after top-level value
[24694] 2016/05/11 21:47:38.719930 [ERR] 10.21.0.3:50747 - rid:7 - Error reading from client: invalid character '"' after top-level value
[24694] 2016/05/11 21:47:38.720570 [ERR] 10.21.0.27:28509 - rid:5 - Error reading from client: invalid character '"' after top-level value
[24694] 2016/05/11 21:47:38.720817 [ERR] 10.21.0.2:7222 - rid:8 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'

Slave 1 (in order of start) (10.21.0.27):

[11497] 2016/05/11 21:36:00.793712 [INF] Starting nats-server version 0.8.0
[11497] 2016/05/11 21:36:00.793786 [INF] Listening for route connections on 10.21.0.27:7222
[11497] 2016/05/11 21:36:00.793849 [INF] Listening for client connections on 0.0.0.0:4222
[11497] 2016/05/11 21:36:00.793880 [INF] Server is ready
[11497] 2016/05/11 21:47:38.719426 [ERR] 10.21.0.35:7222 - rid:5 - Error reading from client: invalid character '"' after top-level value
[11497] 2016/05/11 21:47:38.719929 [ERR] 10.21.0.3:7222 - rid:3 - Error reading from client: invalid character '"' after top-level value
[11497] 2016/05/11 21:47:38.720598 [ERR] 10.21.0.4:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[11497] 2016/05/11 21:47:38.720739 [ERR] 10.21.0.2:7222 - rid:2 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[11497] 2016/05/11 21:47:39.723485 [ERR] 10.21.0.35:32509 - rid:10 - Route Error 'Parser Error'
[11497] 2016/05/11 21:47:39.727319 [ERR] 10.21.0.3:49989 - rid:11 - Route Error 'Parser Error'

Slave 2 (10.21.0.35):

[12341] 2016/05/11 21:36:28.478798 [INF] Starting nats-server version 0.8.0
[12341] 2016/05/11 21:36:28.478926 [INF] Listening for route connections on 10.21.0.35:7222
[12341] 2016/05/11 21:36:28.478996 [INF] Listening for client connections on 0.0.0.0:4222
[12341] 2016/05/11 21:36:28.479030 [INF] Server is ready
[12341] 2016/05/11 21:47:38.718309 [ERR] 10.21.0.3:7222 - rid:1 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[12341] 2016/05/11 21:47:38.719268 [ERR] 10.21.0.4:7222 - rid:2 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[12341] 2016/05/11 21:47:38.719331 [ERR] 10.21.0.2:7222 - rid:3 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[12341] 2016/05/11 21:47:38.719726 [ERR] 10.21.0.27:31937 - rid:4 - Route Error {"server_id":"xn4pmtvOp6Wqr1fJyCKUVf","version":"0.8.0","go":"","host":"10.21.0.28","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.28:7222/"}Parser Error'
[12341] 2016/05/11 21:47:39.722514 [ERR] 10.21.0.28:7222 - rid:8 - Route Error 'Parser Error'
[12341] 2016/05/11 21:47:39.722536 [ERR] 10.21.0.3:60497 - rid:11 - Route Error 'Parser Error'
[12341] 2016/05/11 21:47:39.723487 [ERR] 10.21.0.27:7222 - rid:13 - Error reading from client: invalid character '"' after top-level value

Slave 3 (10.21.0.28):

[18121] 2016/05/11 21:47:38.711869 [INF] Starting nats-server version 0.8.0
[18121] 2016/05/11 21:47:38.711968 [INF] Listening for route connections on 10.21.0.28:7222
[18121] 2016/05/11 21:47:38.712065 [INF] Listening for client connections on 0.0.0.0:4222
[18121] 2016/05/11 21:47:38.712107 [INF] Server is ready
[18121] 2016/05/11 21:47:38.717567 [ERR] 10.21.0.3:7222 - rid:1 - Route Error 'Parser Error'
[18121] 2016/05/11 21:47:39.720371 [ERR] 10.21.0.35:44548 - rid:11 - Error reading from client: invalid character '"' after top-level value

kozlovic added a commit that referenced this issue May 11, 2016
In split buffer conditions, a buffer is used to accumulate bytes.
After processing, this buffer needs to be reset.

Resolves #270
@kozlovic kozlovic self-assigned this May 11, 2016
@awdrius
Copy link
Author

awdrius commented May 11, 2016

@kozlovic Good to know. I didn't get notified about your message so posted that nice wall of text (-.

@kozlovic
Copy link
Member

@awdrius That's fine, sorry for the trouble. I think I have identified the issue and submitted PR #271 that should address this.

@awdrius
Copy link
Author

awdrius commented May 11, 2016

Awesome. I'm happy to be helpful.

@derekcollison
Copy link
Member

@awdrius Feel free to pull from master, 0.8.1 and let us know if the issue is corrected. Thanks again for the feedback.

@awdrius
Copy link
Author

awdrius commented May 12, 2016

@derekcollison Cloned repo and built. Binary reports version 0.8.0beta2 but I can confirm that fix is in place by checking changed source file. Deployed it to 3 seed nodes and 30 slave nodes. I can confirm that I do not see a bunch of cascading errors anymore and /routez reports 32 routes and that number is no longer jumping. I do still see errors in log files.

master-1 (10.21.0.2):

[25159] 2016/05/11 23:41:27.370025 [INF] Starting nats-server version 0.8.0.beta2
[25159] 2016/05/11 23:41:27.370431 [INF] Starting http monitor on 0.0.0.0:8222
[25159] 2016/05/11 23:41:27.370534 [INF] Listening for route connections on 10.21.0.2:7222
[25159] 2016/05/11 23:41:27.370577 [INF] Listening for client connections on 0.0.0.0:4222
[25159] 2016/05/11 23:41:27.370599 [INF] Server is ready
[25159] 2016/05/11 23:49:40.747766 [ERR] 10.21.0.4:49219 - rid:3 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:49:40.749337 [ERR] 10.21.0.3:41825 - rid:1 - Route Error {"server_id":"EB2RwClf6LY74kezPOkhqy","version":"0.8.0.beta2","go":"","host":"10.21.0.12","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.12:7222/"}Parser Error'
[25159] 2016/05/11 23:51:43.149713 [ERR] 10.21.0.18:24511 - rid:9 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.150688 [ERR] 10.21.0.3:42011 - rid:10 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.151365 [ERR] 10.21.0.11:20564 - rid:16 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.152081 [ERR] 10.21.0.12:7222 - rid:5 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.152907 [ERR] 10.21.0.14:41455 - rid:15 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.153529 [ERR] 10.21.0.18:7222 - rid:29 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.160929 [ERR] 10.21.0.4:7222 - rid:8 - Route Error {"server_id":"oqqYaosRcPn6D3nDfTdkQn","version":"0.8.0.beta2","go":"","host":"10.21.0.36","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.36:7222/"}Parser Error'
[25159] 2016/05/11 23:51:43.162364 [ERR] 10.21.0.36:5080 - rid:28 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:43.162937 [ERR] 10.21.0.11:20651 - rid:33 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.545920 [ERR] 10.21.0.9:27129 - rid:17 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.545978 [ERR] 10.21.0.10:7222 - rid:18 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.546243 [ERR] 10.21.0.17:60706 - rid:21 - Route Error 'Parser Error'
[25159] 2016/05/11 23:51:45.547856 [ERR] 10.21.0.25:64994 - rid:70 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.547972 [ERR] 10.21.0.30:46548 - rid:71 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.549205 [ERR] 10.21.0.17:7222 - rid:72 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.549877 [ERR] 10.21.0.12:10177 - rid:34 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.552317 [ERR] 10.21.0.4:7222 - rid:52 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.555678 [ERR] 10.21.0.17:7222 - rid:83 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.557004 [ERR] 10.21.0.30:7222 - rid:82 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.558162 [ERR] 10.21.0.32:7222 - rid:57 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:45.562747 [ERR] 10.21.0.36:7222 - rid:51 - Route Error 'Parser Error'
[25159] 2016/05/11 23:51:45.568465 [ERR] 10.21.0.3:42086 - rid:41 - Route Error 'Parser Error'
[25159] 2016/05/11 23:51:46.287553 [ERR] 10.21.0.19:21773 - rid:124 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.482407 [ERR] 10.21.0.29:7222 - rid:147 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.691726 [ERR] 10.21.0.24:14642 - rid:178 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.692509 [ERR] 10.21.0.15:7222 - rid:23 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.697094 [ERR] 10.21.0.15:7222 - rid:181 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.701206 [ERR] 10.21.0.15:32642 - rid:199 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:46.701949 [ERR] 10.21.0.36:7222 - rid:115 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:47.352503 [ERR] 10.21.0.16:21602 - rid:25 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:47.356545 [ERR] 10.21.0.16:7222 - rid:249 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:47.734404 [ERR] 10.21.0.23:26443 - rid:258 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:49.828601 [ERR] 10.21.0.37:6371 - rid:295 - Error reading from client: invalid character '"' after top-level value
[25159] 2016/05/11 23:51:52.615339 [ERR] 10.21.0.34:18989 - rid:350 - Error reading from client: invalid character '"' after top-level value

master-2 (10.21.0.3):

[24895] 2016/05/11 23:41:38.380592 [INF] Starting nats-server version 0.8.0.beta2
[24895] 2016/05/11 23:41:38.380804 [INF] Starting http monitor on 0.0.0.0:8222
[24895] 2016/05/11 23:41:38.380889 [INF] Listening for route connections on 10.21.0.3:7222
[24895] 2016/05/11 23:41:38.380937 [INF] Listening for client connections on 0.0.0.0:4222
[24895] 2016/05/11 23:41:38.380960 [INF] Server is ready
[24895] 2016/05/11 23:49:40.746847 [ERR] 10.21.0.4:53120 - rid:3 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:49:40.748312 [ERR] 10.21.0.2:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:49:43.877191 [ERR] 10.21.0.10:17211 - rid:20 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.147379 [ERR] 10.21.0.36:7222 - rid:35 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.148758 [ERR] 10.21.0.18:15531 - rid:6 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.149640 [ERR] 10.21.0.14:61879 - rid:14 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.149779 [ERR] 10.21.0.11:6880 - rid:17 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.150079 [ERR] 10.21.0.12:20212 - rid:5 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.150414 [ERR] 10.21.0.4:7222 - rid:7 - Route Error {"server_id":"oqqYaosRcPn6D3nDfTdkQn","version":"0.8.0.beta2","go":"","host":"10.21.0.36","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.36:7222/"}Parser Error'
[24895] 2016/05/11 23:51:43.151381 [ERR] 10.21.0.2:7222 - rid:8 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.154301 [ERR] 10.21.0.11:7222 - rid:38 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.155649 [ERR] 10.21.0.18:7222 - rid:37 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:43.156819 [ERR] 10.21.0.14:7222 - rid:40 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.542432 [ERR] 10.21.0.9:7222 - rid:18 - Route Error {"server_id":"2MblphGmkg60y03IrzRLO8","version":"0.8.0.beta2","go":"","host":"10.21.0.32","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.32:7222/"}Parser Error'
[24895] 2016/05/11 23:51:45.542647 [ERR] 10.21.0.10:7222 - rid:21 - Route Error {"server_id":"2MblphGmkg60y03IrzRLO8","version":"0.8.0.beta2","go":"","host":"10.21.0.32","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.32:7222/"}Parser Error'
[24895] 2016/05/11 23:51:45.544648 [ERR] 10.21.0.17:60791 - rid:28 - Route Error 'Parser Error'
[24895] 2016/05/11 23:51:45.547197 [ERR] 10.21.0.25:6259 - rid:71 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.548376 [ERR] 10.21.0.9:7222 - rid:73 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.551352 [ERR] 10.21.0.30:7222 - rid:74 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.558266 [ERR] 10.21.0.10:7222 - rid:72 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.560278 [ERR] 10.21.0.17:7222 - rid:77 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.561255 [ERR] 10.21.0.25:7222 - rid:85 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.563059 [ERR] 10.21.0.4:7222 - rid:60 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.563674 [ERR] 10.21.0.2:7222 - rid:49 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.567555 [ERR] 10.21.0.36:47667 - rid:36 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:45.813436 [ERR] 10.21.0.20:6864 - rid:110 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:46.481487 [ERR] 10.21.0.29:24713 - rid:116 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:46.682473 [ERR] 10.21.0.24:7222 - rid:148 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:46.684418 [ERR] 10.21.0.15:45734 - rid:29 - Route Error {"server_id":"5q71bPewlOKmhddReWNwrg","version":"0.8.0.beta2","go":"","host":"10.21.0.24","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.24:7222/"}Parser Error'
[24895] 2016/05/11 23:51:47.351716 [ERR] 10.21.0.16:7222 - rid:30 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:47.505676 [ERR] 10.21.0.31:7222 - rid:185 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:47.733469 [ERR] 10.21.0.23:57464 - rid:201 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:47.863500 [ERR] 10.21.0.28:30688 - rid:222 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:48.593505 [ERR] 10.21.0.26:10013 - rid:251 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.641439 [ERR] 10.21.0.21:43359 - rid:281 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.709225 [ERR] 10.21.0.33:7222 - rid:288 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.711744 [ERR] 10.21.0.21:7222 - rid:287 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.724111 [ERR] 10.21.0.24:7222 - rid:151 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.725633 [ERR] 10.21.0.33:7222 - rid:289 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.727096 [ERR] 10.21.0.23:7222 - rid:204 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.761358 [ERR] 10.21.0.33:7222 - rid:293 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.767856 [ERR] 10.21.0.23:57589 - rid:309 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.826205 [ERR] 10.21.0.21:7222 - rid:304 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.843653 [ERR] 10.21.0.37:38602 - rid:320 - Error reading from client: invalid character '"' after top-level value
[24895] 2016/05/11 23:51:49.867997 [ERR] 10.21.0.23:57596 - rid:313 - Route Error 'Parser Error'
[24895] 2016/05/11 23:51:49.917486 [ERR] 10.21.0.19:7222 - rid:114 - Error reading from client: invalid character '"' after top-level value

master-3 (10.21.0.4):

[25209] 2016/05/11 23:41:47.251309 [INF] Starting nats-server version 0.8.0.beta2
[25209] 2016/05/11 23:41:47.251526 [INF] Starting http monitor on 0.0.0.0:8222
[25209] 2016/05/11 23:41:47.251759 [INF] Listening for route connections on 10.21.0.4:7222
[25209] 2016/05/11 23:41:47.251937 [INF] Listening for client connections on 0.0.0.0:4222
[25209] 2016/05/11 23:41:47.252088 [INF] Server is ready
[25209] 2016/05/11 23:49:40.746981 [ERR] 10.21.0.3:7222 - rid:2 - Route Error {"server_id":"EB2RwClf6LY74kezPOkhqy","version":"0.8.0.beta2","go":"","host":"10.21.0.12","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.12:7222/"}Parser Error'
[25209] 2016/05/11 23:49:40.748221 [ERR] 10.21.0.2:7222 - rid:1 - Route Error {"server_id":"EB2RwClf6LY74kezPOkhqy","version":"0.8.0.beta2","go":"","host":"10.21.0.12","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.12:7222/"}Parser Error'
[25209] 2016/05/11 23:49:43.877373 [ERR] 10.21.0.10:7222 - rid:31 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.148773 [ERR] 10.21.0.18:18639 - rid:10 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.149785 [ERR] 10.21.0.12:7222 - rid:7 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.149836 [ERR] 10.21.0.14:25373 - rid:18 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.149908 [ERR] 10.21.0.3:53276 - rid:11 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.150059 [ERR] 10.21.0.11:7222 - rid:22 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.150773 [ERR] 10.21.0.2:43257 - rid:9 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.151043 [ERR] 10.21.0.18:7222 - rid:51 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.152966 [ERR] 10.21.0.36:7222 - rid:49 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.155257 [ERR] 10.21.0.12:7222 - rid:52 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.159458 [ERR] 10.21.0.14:7222 - rid:57 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:43.160200 [ERR] 10.21.0.18:7222 - rid:55 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.544526 [ERR] 10.21.0.10:7222 - rid:34 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.545731 [ERR] 10.21.0.9:7222 - rid:29 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.546220 [ERR] 10.21.0.17:7222 - rid:40 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.549350 [ERR] 10.21.0.25:2493 - rid:102 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.550846 [ERR] 10.21.0.32:62512 - rid:91 - Route Error 'Parser Error'
[25209] 2016/05/11 23:51:45.552569 [ERR] 10.21.0.17:7222 - rid:111 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.555389 [ERR] 10.21.0.2:43310 - rid:81 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.560807 [ERR] 10.21.0.30:7222 - rid:106 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.562448 [ERR] 10.21.0.10:35731 - rid:107 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:45.563777 [ERR] 10.21.0.3:53357 - rid:79 - Route Error 'Parser Error'
[25209] 2016/05/11 23:51:45.566159 [ERR] 10.21.0.36:33124 - rid:78 - Route Error 'Parser Error'
[25209] 2016/05/11 23:51:45.567173 [ERR] 10.21.0.25:2526 - rid:121 - Route Error 'Parser Error'
[25209] 2016/05/11 23:51:46.291334 [ERR] 10.21.0.19:51656 - rid:150 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:46.481574 [ERR] 10.21.0.29:35587 - rid:162 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:46.686796 [ERR] 10.21.0.24:61647 - rid:193 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:46.688625 [ERR] 10.21.0.15:7222 - rid:43 - Route Error {"server_id":"5q71bPewlOKmhddReWNwrg","version":"0.8.0.beta2","go":"","host":"10.21.0.24","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.24:7222/"}Parser Error'
[25209] 2016/05/11 23:51:46.690606 [ERR] 10.21.0.24:7222 - rid:190 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:46.694291 [ERR] 10.21.0.15:7222 - rid:214 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:47.351584 [ERR] 10.21.0.16:37990 - rid:47 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:47.866106 [ERR] 10.21.0.28:41792 - rid:266 - Error reading from client: invalid character '"' after top-level value
[25209] 2016/05/11 23:51:49.711900 [ERR] 10.21.0.33:42544 - rid:315 - Error reading from client: invalid character '"' after top-level value

Random slave (10.21.0.12):

[827] 2016/05/11 23:49:40.369469 [INF] Starting nats-server version 0.8.0.beta2
[827] 2016/05/11 23:49:40.370738 [INF] Listening for route connections on 10.21.0.12:7222
[827] 2016/05/11 23:49:40.370890 [INF] Listening for client connections on 0.0.0.0:4222
[827] 2016/05/11 23:49:40.370948 [INF] Server is ready
[827] 2016/05/11 23:49:42.643024 [ERR] 10.21.0.11:7222 - rid:16 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:49:43.509642 [ERR] 10.21.0.10:7222 - rid:36 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.148718 [ERR] 10.21.0.18:7222 - rid:11 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149620 [ERR] 10.21.0.3:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149680 [ERR] 10.21.0.14:7222 - rid:13 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149713 [ERR] 10.21.0.11:7222 - rid:29 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149816 [ERR] 10.21.0.4:51702 - rid:6 - Route Error {"server_id":"oqqYaosRcPn6D3nDfTdkQn","version":"0.8.0.beta2","go":"","host":"10.21.0.36","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.36:7222/"}Parser Error'
[827] 2016/05/11 23:51:43.150431 [ERR] 10.21.0.2:54504 - rid:3 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.158658 [ERR] 10.21.0.4:51764 - rid:78 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:43.163504 [ERR] 10.21.0.14:7222 - rid:73 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:45.544556 [ERR] 10.21.0.10:7222 - rid:37 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:45.544613 [ERR] 10.21.0.9:7222 - rid:31 - Route Error {"server_id":"2MblphGmkg60y03IrzRLO8","version":"0.8.0.beta2","go":"","host":"10.21.0.32","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.32:7222/"}Parser Error'
[827] 2016/05/11 23:51:45.545729 [ERR] 10.21.0.17:7222 - rid:45 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:45.549022 [ERR] 10.21.0.2:7222 - rid:84 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:45.551933 [ERR] 10.21.0.17:7222 - rid:111 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.481424 [ERR] 10.21.0.29:7222 - rid:138 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.690483 [ERR] 10.21.0.15:7222 - rid:48 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.690699 [ERR] 10.21.0.24:7222 - rid:164 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:47.351299 [ERR] 10.21.0.16:7222 - rid:50 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:52.701579 [ERR] 10.21.0.34:7222 - rid:400 - Error reading from client: invalid character '"' after top-level value
e ():
[827] 2016/05/11 23:49:40.369469 [INF] Starting nats-server version 0.8.0.beta2
[827] 2016/05/11 23:49:40.370738 [INF] Listening for route connections on 10.21.0.12:7222
[827] 2016/05/11 23:49:40.370890 [INF] Listening for client connections on 0.0.0.0:4222
[827] 2016/05/11 23:49:40.370948 [INF] Server is ready
[827] 2016/05/11 23:49:42.643024 [ERR] 10.21.0.11:7222 - rid:16 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:49:43.509642 [ERR] 10.21.0.10:7222 - rid:36 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.148718 [ERR] 10.21.0.18:7222 - rid:11 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149620 [ERR] 10.21.0.3:7222 - rid:1 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149680 [ERR] 10.21.0.14:7222 - rid:13 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149713 [ERR] 10.21.0.11:7222 - rid:29 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.149816 [ERR] 10.21.0.4:51702 - rid:6 - Route Error {"server_id":"oqqYaosRcPn6D3nDfTdkQn","version":"0.8.0.beta2","go":"","host":"10.21.0.36","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.36:7222/"}Parser Error'
[827] 2016/05/11 23:51:43.150431 [ERR] 10.21.0.2:54504 - rid:3 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:43.158658 [ERR] 10.21.0.4:51764 - rid:78 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:43.163504 [ERR] 10.21.0.14:7222 - rid:73 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:45.544556 [ERR] 10.21.0.10:7222 - rid:37 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:45.544613 [ERR] 10.21.0.9:7222 - rid:31 - Route Error {"server_id":"2MblphGmkg60y03IrzRLO8","version":"0.8.0.beta2","go":"","host":"10.21.0.32","port":7222,"auth_required":false,"ssl_required":false,"tls_required":false,"tls_verify":false,"max_payload":1048576,"ip":"nats-route://10.21.0.32:7222/"}Parser Error'
[827] 2016/05/11 23:51:45.545729 [ERR] 10.21.0.17:7222 - rid:45 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:45.549022 [ERR] 10.21.0.2:7222 - rid:84 - Route Error 'Parser Error'
[827] 2016/05/11 23:51:45.551933 [ERR] 10.21.0.17:7222 - rid:111 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.481424 [ERR] 10.21.0.29:7222 - rid:138 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.690483 [ERR] 10.21.0.15:7222 - rid:48 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:46.690699 [ERR] 10.21.0.24:7222 - rid:164 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:47.351299 [ERR] 10.21.0.16:7222 - rid:50 - Error reading from client: invalid character '"' after top-level value
[827] 2016/05/11 23:51:52.701579 [ERR] 10.21.0.34:7222 - rid:400 - Error reading from client: invalid character '"' after top-level value

I have a single service that subscribes to 2 subjects and a test requester and can confirm that request-reply (on Queue subscribers) work fine.

I'm going to run more tests tomorrow and will report any findings.

@derekcollison
Copy link
Member

Master builds should report 0.8.1 version, can you double check?

@kozlovic
Copy link
Member

Yes, either those are older logs (I am not sure you would be able to get the full mesh with the prior bug) and the version should definitively report something else. Maybe some caching issue?

@awdrius
Copy link
Author

awdrius commented May 12, 2016

I build gnats fallowing Building of the docs (go build). I now have a version built using Dockerfile in git repo root and will deploy it shortly.

As for 0.8.0beta2 I restarted one gnatsd instance on one of the slaves and I got that cascading thing again (with /routez reporting num_routes jumping up and down) but it stabilized after couple of seconds.

I'll follow up with the results of the 0.8.1 version.

@awdrius
Copy link
Author

awdrius commented May 12, 2016

@derekcollison @kozlovic I can confirm that it works flawlessly with gnatsd 0.8.1. No more errors in logs, no more route number going up and down upon a single gnatsd instance restart.

Apologies for the false alarm previously and thanks for the quick turnaround.

@kozlovic
Copy link
Member

Glad to know it works now! And again, thank you for the report.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants