nsqadmin: missing channel from topic list #753

jehiah · 2018-07-31T06:02:31Z

the api endpoint /api/topics/:topic seems to be missing a channel that i see in /stats output from nsqd's. I'm not sure what the bug is yet, but this causes it to be missing from the nsqadmin UI at /topics/:topic even though it shows properly if you manually navigate to /topics/:topic/:channel.

mreiferson · 2016-05-02T18:15:42Z

I'm looking forward to the explanation on this one

chrusty · 2016-05-04T10:35:39Z

I've seen the same thing recently with NSQ 0.3.6

jehiah · 2016-05-04T12:46:14Z

thanks @chrusty that's helpful confirmation. This was with 0.3.6-alpha+build.27.967fce5

I had to resolve the production situation where i observed this, and wasn't able to reproduce this easily in a development environment so it might take me longer than i had hoped to track this down.

chrusty · 2016-05-06T17:57:02Z

After having a look around, I'm beginning to wonder if this could be a symptom of having my system-clocks out of sync. Recently some of my system clocks have skewed a bit and I know it has caused issues for some of the databases I'm using (this is pretty shameful, I know).

This is still pretty vague, I know.

jehiah · 2017-06-23T20:26:09Z

I appear to have stumbled upon another case of this in production. with version 1.0.0-alpha+build.7.ea01a579

The general situation is that given 10 servers, this happens where only one nsqd has a an extra channel. It's reported and returned properly from every nsqlookupd, and returned properly from the individual nsqd stats endpoints. Nsqadmin also properly queries the nsqd node with the odd channel.

I'm including redacted nsqadmin logs, nsqlookup output and nsqd stats output. In this example the channel queuereader_m is missing from the nsqadmin page for events.

[nsqadmin] 2017/06/23 20:12:08.345616 CI: querying nsqlookupd http://lookup05:4161/lookup?topic=events
[nsqadmin] 2017/06/23 20:12:08.345634 CI: querying nsqlookupd http://lookup04:4161/lookup?topic=events
[nsqadmin] 2017/06/23 20:12:08.345672 CI: querying nsqlookupd http://lookup03:4161/lookup?topic=events
[nsqadmin] 2017/06/23 20:12:08.345620 CI: querying nsqlookupd http://lookup02:4161/lookup?topic=events
[nsqadmin] 2017/06/23 20:12:08.345624 CI: querying nsqlookupd http://lookup01:4161/lookup?topic=events
[nsqadmin] 2017/06/23 20:12:08.348347 CI: querying nsqd http://a01:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348354 CI: querying nsqd http://a11:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348358 CI: querying nsqd http://s02:4151/stats?format=json <---
[nsqadmin] 2017/06/23 20:12:08.348370 CI: querying nsqd http://a12:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348359 CI: querying nsqd http://a05:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348422 CI: querying nsqd http://s03:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348364 CI: querying nsqd http://s01:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348442 CI: querying nsqd http://a09:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348472 CI: querying nsqd http://a01:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348351 CI: querying nsqd http://a03:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348516 CI: querying nsqd http://a10:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348575 CI: querying nsqd http://a02:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.348615 CI: querying nsqd http://a13:4151/stats?format=json
[nsqadmin] 2017/06/23 20:12:08.380435 200 GET /api/topics/events (127.0.0.1:56997) 34.826237ms

$ curl 'http://lookup01:4161/lookup?topic=events' | jq .
{
  "producers": [
    {
      "version": "1.0.0-alpha+build.7.ea01a579",
      "http_port": 4151,
      "tcp_port": 4150,
      "broadcast_address": "a01",
      "hostname": "a01",
      "remote_address": "1.2.3.4:58636"
    },
    {
      "version": "1.0.0-alpha+build.7.ea01a579",
      "http_port": 4151,
      "tcp_port": 4150,
      "broadcast_address": "s01",
      "hostname": "s01",
      "remote_address": "1.2.3.5:34638"
    },
	// other hosts
  ],
  "channels": [
    "others....",
    "queuereader_m",
    "others..."
  ]
}

$ curl 'http://s02:4151/stats?format=json'
{
  "topics": [
	{
      "e2e_processing_latency": {
        "percentiles": null,
        "count": 0
      },
      "paused": false,
      "message_count": 1110,
      "backend_depth": 0,
      "depth": 0,
      "channels": [
		{....}, // other channels
        {
          "e2e_processing_latency": {
            "percentiles": null,
            "count": 0
          },
          "paused": false,
          "clients": [],
          "channel_name": "queuereader_m",
          "depth": 9517,
          "backend_depth": 8407,
          "in_flight_count": 0,
          "deferred_count": 0,
          "message_count": 1110,
          "requeue_count": 0,
          "timeout_count": 0
        },	
      ],
      "topic_name": "events"
    },
  ],
  "start_time": 1497479679,
  "health": "OK",
  "version": "1.0.0-alpha+build.7.ea01a579"
}

mreiferson · 2017-06-25T22:15:53Z

@jehiah so you think this is a bug in nsqadmin query/parsing/aggregation or the frontend displaying the results?

jehiah · 2017-06-25T22:51:32Z

I think it's a nsqadmin aggregation bug. I suspect the aggregation somehow only returns items that are in the first nsq stats output it parses.

Unfortunately I forgot to capture the matching nsqadmin API output.

mreiferson · 2017-06-26T15:07:43Z

@jehiah you intend to take this one?

jehiah · 2017-06-26T18:29:18Z

not immediately

ploxiln · 2017-09-24T23:55:02Z

I've run into something probably unrelated but possibly sometimes giving similar symptoms: nsqadmin seems to keep and re-use http client connections after a week or so of inactivity, but they don't work (presumably because the AWS EC2 security-groups firewall forgot the connection) and they time out. Then on the second (and further) attempts to load the same page, it uses a new connection and works instantly.

I started noticing this a month or two ago, and once the pattern was figured out, it is surprisingly consistent. I load up nsqadmin after leaving it alone for a full week or so, and go to the "Nodes" list page, and then go to individual an nsqd node page. (So it makes a stats request to just one nsqd for the page. This also affects topic and channel pages, but multiple nsqd at a time. So for isolating the issue I used nodes.) For every single nsqd, the first time, the request times out. Later times works.

I can curl nsqd stats, while on the nsqadmin server, just before loading the node page for that nsqd. Curl works first time, nsqadmin fails first time. I did tcpdump once, and was able to confirm that there was no SYN etc on the first attempt, just an http request on a theoretically existing connection, then a bunch of TCP retransmissions.

The crazy part is that there are multiple reasons why this should be impossible. First, I've ensured /proc/sys/net/ipv4/tcp_keepalive_{time,intvl,probes} is set (to {540,45,3} in my case but the default {7200,75,9} should also work). Second, I don't see this behavior after just 24 or 36 hours, I have to wait about a week to see it. Third, go added a work-around for this common problem in early 2016: https://go-review.googlesource.com/c/go/+/22670

I'm using an nsqadmin built from the master branch in early August, with go-1.8.3 on macOS cross-building for linux.

EDIT: fixed typo of missing critical "no" in "no SYN"

EDIT2: after reading more, I've learned that os/kernel configuration of tcp keepalive is not enough to enable it, the process must enable it on a socket with setsockopt(... SO_KEEPALIVE ...) as well. I'm still not sure why the golang Transport feature is not working though

EDIT3: that's because nsq/internal/http_api/api_request.go:NewDeadlineTransport() creates a new transport without the MaxIdle stuff. that stuff was added in go-1.7

…hannels

jehiah · 2018-07-31T06:07:11Z

RFR @mreiferson @ploxiln

I was able to reproduce this bug with the following setup

Node A: topic: T channels a,b,c
Node B: topic: T channels a.

With that setup the count was previously 3 on both nodes, and depending on the order /stats responses completed you would see all three channels listed on the topics page, or just one.

ploxiln · 2018-07-31T14:40:21Z

internal/clusterinfo/types.go

 	for _, aChannelStats := range a.Channels {
+		found := false


nice fix 👍

it only took me about a hundred printf's to find it =)

ploxiln · 2018-07-31T14:42:20Z

nsqadmin/static/js/views/topic.hbs

@@ -81,7 +81,7 @@
            {{#if ../graph_active}}
                <td class="bold rate" target="{{rate "topic" node topic_name ""}}"></td>
            {{/if}}
-            <td>{{commafy ../channels.length}}</td>
+            <td>{{commafy this/channels.length}}</td>


this is greek to me :)
I wonder if "this/" is not needed and just "channels.length" would suffice?

I'm not sure... I confused myself by working in the wrong part of the template for a while, but there is a global channels var so this is at least more explicit.

fair enough :) no objection

mreiferson

LGTM, nice catch

jehiah added the bug label May 2, 2016

mreiferson added the needs info label Jan 2, 2017

jehiah added 2 commits July 31, 2018 02:04

nsqadmin: fix channel count on topic page when nodes have different c…

cb6fd8b

…hannels

nsqadmin: fix channel list when nodes have unequal channel lists

598e111

jehiah force-pushed the nsqadmin_fix_753 branch from 4961787 to 598e111 Compare July 31, 2018 06:04

jehiah requested review from mreiferson and ploxiln July 31, 2018 06:05

ploxiln reviewed Jul 31, 2018

View reviewed changes

ploxiln approved these changes Jul 31, 2018

View reviewed changes

mreiferson removed the needs info label Jul 31, 2018

mreiferson approved these changes Jul 31, 2018

View reviewed changes

mreiferson merged commit f0dd3c3 into nsqio:master Jul 31, 2018

mreiferson deleted the nsqadmin_fix_753 branch July 31, 2018 14:54

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

nsqadmin: missing channel from topic list #753

nsqadmin: missing channel from topic list #753

jehiah commented Jul 31, 2018

mreiferson commented May 2, 2016

chrusty commented May 4, 2016

jehiah commented May 4, 2016

chrusty commented May 6, 2016

jehiah commented Jun 23, 2017

mreiferson commented Jun 25, 2017

jehiah commented Jun 25, 2017

mreiferson commented Jun 26, 2017

jehiah commented Jun 26, 2017

ploxiln commented Sep 24, 2017 •

edited

Loading

jehiah commented Jul 31, 2018

ploxiln Jul 31, 2018

jehiah Jul 31, 2018

ploxiln Jul 31, 2018

jehiah Jul 31, 2018

ploxiln Jul 31, 2018

mreiferson left a comment

nsqadmin: missing channel from topic list #753

nsqadmin: missing channel from topic list #753

Conversation

jehiah commented Jul 31, 2018

mreiferson commented May 2, 2016

chrusty commented May 4, 2016

jehiah commented May 4, 2016

chrusty commented May 6, 2016

jehiah commented Jun 23, 2017

mreiferson commented Jun 25, 2017

jehiah commented Jun 25, 2017

mreiferson commented Jun 26, 2017

jehiah commented Jun 26, 2017

ploxiln commented Sep 24, 2017 • edited Loading

jehiah commented Jul 31, 2018

ploxiln Jul 31, 2018

Choose a reason for hiding this comment

jehiah Jul 31, 2018

Choose a reason for hiding this comment

ploxiln Jul 31, 2018

Choose a reason for hiding this comment

jehiah Jul 31, 2018

Choose a reason for hiding this comment

ploxiln Jul 31, 2018

Choose a reason for hiding this comment

mreiferson left a comment

Choose a reason for hiding this comment

ploxiln commented Sep 24, 2017 •

edited

Loading