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.

Sign up for GitHub

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

Jump to bottom

nsqadmin: handle eventually consistent topic creation #1248

Open
jreyeshdez opened this issue Apr 27, 2020 · 8 comments
Open

nsqadmin: handle eventually consistent topic creation #1248

jreyeshdez opened this issue Apr 27, 2020 · 8 comments
Labels
bug

Comments

@jreyeshdez
Copy link

jreyeshdez commented Apr 27, 2020 •
edited
Loading

I have a set up that starts nsqlookupd, nsqd and nsqadmin from an bash script that gets called from a cloud-init file in a EC2 instance.

The whole setup works. I can browse to http://ec2-public-ip.aws-region.compute.amazonaws.com:port/lookup and create a Topic however when I click over the inactive topic I get the following error in the UI UPSTREAM_ERROR: Failed to query any nsqd: and following error in the nsqadmin logs:

# [nsqadmin] 2020/04/27 16:59:01.454151 INFO: 200 GET /api/topics (33.222.333.555:49005) 754.952µs
# [nsqadmin] 2020/04/27 17:01:19.216780 INFO: CI: querying nsqlookupd http://192.32.45.224:9012/lookup?topic=test
# [nsqadmin] 2020/04/27 17:01:19.217070 INFO: CI: querying nsqlookupd http://192.32.45.224:9011/lookup?topic=test
# [nsqadmin] 2020/04/27 17:01:19.218032 ERROR: failed to get topic metadata - Failed to query any nsqd:
# [nsqadmin] 2020/04/27 17:01:19.218056 INFO: 502 GET /api/topics/test (33.222.333.555:49034) 1.303874ms

This is part of the script that starts nsq:

for NODE in {1..2};
do
    HOSTNAME="nsqlookupd-0$NODE"
    echo -e "$ThisPrivateIpAddress\t$HOSTNAME" >> $ETC_HOSTS
    /usr/local/bin/nsqlookupd \
        -broadcast-address="$HOSTNAME" \
        -log-level="debug" \
        -tcp-address="$ThisPrivateIpAddress:900$NODE" \
        -http-address="$ThisPrivateIpAddress:901$NODE" >> "$NSQLOOKUPD_LOG" 2>&1 &
done

for NODE in {1..5};
do
    HOSTNAME="nsqd-0$NODE"
    echo -e "$ThisPrivateIpAddress\t$HOSTNAME" >> $ETC_HOSTS
    mkdir -p "$HOME/nsqd/$HOSTNAME"
    /usr/local/bin/nsqd \
        -broadcast-address="$HOSTNAME" \
        -data-path="$HOME/nsqd/$HOSTNAME" \
        -tcp-address="$ThisPublicDnsName:903$NODE" \
        -http-address="$ThisPublicDnsName:904$NODE" \
        -auth-http-address="$ThisPublicDnsName:4181" \
        -lookupd-tcp-address="$ThisPrivateIpAddress:9001" \
        -lookupd-tcp-address="$ThisPrivateIpAddress:9002" >> "$NSQD_LOG" 2>&1 &
done

/usr/local/bin/nsqadmin \
    -http-address="$ThisPublicDnsName:9000" \
    -lookupd-http-address="$ThisPrivateIpAddress:9011" \
    -lookupd-http-address="$ThisPrivateIpAddress:9012" >> "$NSQADMIN_LOG" 2>&1 &

The $ThisPublicDnsName, $ThisPrivateDnsName, $ThisPrivateIpAddress are retrieved by using aws cli ec2 describe-instances.

If I create a consumer and connect to any of the tcp addresses for nsqd and subscribe to a topic then it works, however topic gets created as it does not exist and the previous GET /api/topics/test works in the UI where I can see the info about consumers/producers for that topic. If the topic got created via UI also works if connecting the consumer/producer. On the other hand if I try to create another topic via http://ec2-public-ip.aws-region.compute.amazonaws.com:port/lookup then same problem occurs.

From above script I am mapping the ip hostname (-broadcast-address) in /etc/hosts so not sure what I am missing.
@ploxiln
Copy link
Member

ploxiln commented Apr 27, 2020

I'd call it a known limitation - but nsqadmin should probably handle it more gracefully.

The purpose of creating topics with nsqadmin, is to also be able to pre-create channels (these are all registered in nsqlookupd). When some service starts producing/publishing messages of that topic, it will send it to a pre-configured nsqd (or pool), often "localhost". That nsqd will create the topic locally, and pre-populate the channels with the list of existing channels from nsqlookupd. This way, if there will be multiple channels, messages won't be lost on channels other than the first to be created on an nsqd, by consumers when they connect. (Consumers typically use nsqlookupd to find all nsqd instances/servers which have a topic.)

nsqadmin expects that topics must exist on some nsqd ... and that's usually true ... but it does enable the case when it is briefly false, so that should be made more graceful.

@ploxiln ploxiln added the bug label Apr 27, 2020
@mreiferson
Copy link
Member

@jreyeshdez can you share the logs from the other daemons running (e.g. nsqd and nsqlookupd)

@mreiferson mreiferson changed the title Unable to see stats for topics created from nsqadmin UI nsqadmin: handle eventually consistent topic creation Jun 11, 2020
@jreyeshdez
Copy link
Author

jreyeshdez commented Jun 11, 2020 •
edited
Loading

@jreyeshdez can you share the logs from the other daemons running (e.g. nsqd and nsqlookupd)

Sorry for the formatting. Edit (Splitting it into two comments)

nsqd logs: 
[nsqd] 2020/04/27 16:52:54.250036 INFO: nsqd v1.2.0 (built w/go1.12.9)
[nsqd] 2020/04/27 16:52:54.252488 INFO: nsqd v1.2.0 (built w/go1.12.9)
[nsqd] 2020/04/27 16:52:54.252516 INFO: ID: 864
[nsqd] 2020/04/27 16:52:54.254063 INFO: ID: 864
[nsqd] 2020/04/27 16:52:54.258012 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-01/nsqd.dat
[nsqd] 2020/04/27 16:52:54.259789 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-02/nsqd.dat
[nsqd] 2020/04/27 16:52:54.264518 INFO: LOOKUP(172.31.47.238:9001): adding peer
[nsqd] 2020/04/27 16:52:54.264556 INFO: LOOKUP connecting to 172.31.47.238:9001
[nsqd] 2020/04/27 16:52:54.264910 INFO: TCP: listening on 172.31.47.238:9031
[nsqd] 2020/04/27 16:52:54.264950 INFO: HTTP: listening on 172.31.47.238:9041
[nsqd] 2020/04/27 16:52:54.265601 INFO: LOOKUPD(172.31.47.238:9001): peer info {TCPPort:9001 HTTPPort:9011 Version:1.2.0 BroadcastAddress:nsqlookupd-01}
[nsqd] 2020/04/27 16:52:54.265628 INFO: LOOKUP(172.31.47.238:9002): adding peer
[nsqd] 2020/04/27 16:52:54.265635 INFO: LOOKUP connecting to 172.31.47.238:9002
[nsqd] 2020/04/27 16:52:54.266287 INFO: LOOKUPD(172.31.47.238:9002): peer info {TCPPort:9002 HTTPPort:9012 Version:1.2.0 BroadcastAddress:nsqlookupd-02}
[nsqd] 2020/04/27 16:52:54.258281 INFO: nsqd v1.2.0 (built w/go1.12.9)
[nsqd] 2020/04/27 16:52:54.266607 INFO: ID: 864
[nsqd] 2020/04/27 16:52:54.277946 INFO: nsqd v1.2.0 (built w/go1.12.9)
[nsqd] 2020/04/27 16:52:54.279714 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-03/nsqd.dat
[nsqd] 2020/04/27 16:52:54.279890 INFO: ID: 864
[nsqd] 2020/04/27 16:52:54.284371 INFO: LOOKUP(172.31.47.238:9001): adding peer
[nsqd] 2020/04/27 16:52:54.284399 INFO: LOOKUP connecting to 172.31.47.238:9001
[nsqd] 2020/04/27 16:52:54.285069 INFO: LOOKUPD(172.31.47.238:9001): peer info {TCPPort:9001 HTTPPort:9011 Version:1.2.0 BroadcastAddress:nsqlookupd-01}
[nsqd] 2020/04/27 16:52:54.285096 INFO: LOOKUP(172.31.47.238:9002): adding peer
[nsqd] 2020/04/27 16:52:54.285103 INFO: LOOKUP connecting to 172.31.47.238:9002
[nsqd] 2020/04/27 16:52:54.285672 INFO: LOOKUPD(172.31.47.238:9002): peer info {TCPPort:9002 HTTPPort:9012 Version:1.2.0 BroadcastAddress:nsqlookupd-02}
[nsqd] 2020/04/27 16:52:54.285721 INFO: TCP: listening on 172.31.47.238:9033
[nsqd] 2020/04/27 16:52:54.285746 INFO: HTTP: listening on 172.31.47.238:9043
[nsqd] 2020/04/27 16:52:54.286847 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-04/nsqd.dat
[nsqd] 2020/04/27 16:52:54.287064 INFO: LOOKUP(172.31.47.238:9001): adding peer
[nsqd] 2020/04/27 16:52:54.287076 INFO: LOOKUP connecting to 172.31.47.238:9001
[nsqd] 2020/04/27 16:52:54.287818 INFO: LOOKUPD(172.31.47.238:9001): peer info {TCPPort:9001 HTTPPort:9011 Version:1.2.0 BroadcastAddress:nsqlookupd-01}
[nsqd] 2020/04/27 16:52:54.287852 INFO: LOOKUP(172.31.47.238:9002): adding peer
[nsqd] 2020/04/27 16:52:54.287884 INFO: LOOKUP connecting to 172.31.47.238:9002
[nsqd] 2020/04/27 16:52:54.288450 INFO: LOOKUPD(172.31.47.238:9002): peer info {TCPPort:9002 HTTPPort:9012 Version:1.2.0 BroadcastAddress:nsqlookupd-02}
[nsqd] 2020/04/27 16:52:54.288538 INFO: TCP: listening on 172.31.47.238:9032
[nsqd] 2020/04/27 16:52:54.289779 INFO: HTTP: listening on 172.31.47.238:9042
[nsqd] 2020/04/27 16:52:54.289852 INFO: nsqd v1.2.0 (built w/go1.12.9)
[nsqd] 2020/04/27 16:52:54.289879 INFO: ID: 864
[nsqd] 2020/04/27 16:52:54.291662 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-05/nsqd.dat
[nsqd] 2020/04/27 16:52:54.297656 INFO: LOOKUP(172.31.47.238:9001): adding peer
[nsqd] 2020/04/27 16:52:54.297768 INFO: LOOKUP connecting to 172.31.47.238:9001
[nsqd] 2020/04/27 16:52:54.298471 INFO: LOOKUPD(172.31.47.238:9001): peer info {TCPPort:9001 HTTPPort:9011 Version:1.2.0 BroadcastAddress:nsqlookupd-01}
[nsqd] 2020/04/27 16:52:54.298492 INFO: LOOKUP(172.31.47.238:9002): adding peer
[nsqd] 2020/04/27 16:52:54.298499 INFO: LOOKUP connecting to 172.31.47.238:9002
[nsqd] 2020/04/27 16:52:54.299066 INFO: LOOKUPD(172.31.47.238:9002): peer info {TCPPort:9002 HTTPPort:9012 Version:1.2.0 BroadcastAddress:nsqlookupd-02}
[nsqd] 2020/04/27 16:52:54.299103 INFO: TCP: listening on 172.31.47.238:9034
[nsqd] 2020/04/27 16:52:54.299133 INFO: HTTP: listening on 172.31.47.238:9044
[nsqd] 2020/04/27 16:52:54.306230 INFO: LOOKUP(172.31.47.238:9001): adding peer
[nsqd] 2020/04/27 16:52:54.306244 INFO: LOOKUP connecting to 172.31.47.238:9001
[nsqd] 2020/04/27 16:52:54.306914 INFO: LOOKUPD(172.31.47.238:9001): peer info {TCPPort:9001 HTTPPort:9011 Version:1.2.0 BroadcastAddress:nsqlookupd-01}
[nsqd] 2020/04/27 16:52:54.306935 INFO: LOOKUP(172.31.47.238:9002): adding peer
[nsqd] 2020/04/27 16:52:54.306940 INFO: LOOKUP connecting to 172.31.47.238:9002
[nsqd] 2020/04/27 16:52:54.307486 INFO: LOOKUPD(172.31.47.238:9002): peer info {TCPPort:9002 HTTPPort:9012 Version:1.2.0 BroadcastAddress:nsqlookupd-02}
[nsqd] 2020/04/27 16:52:54.307523 INFO: TCP: listening on 172.31.47.238:9035
[nsqd] 2020/04/27 16:52:54.307546 INFO: HTTP: listening on 172.31.47.238:9045
[nsqd] 2020/04/27 17:47:09.571032 INFO: TCP: new client(37.228.253.250:49059)
[nsqd] 2020/04/27 17:47:09.571126 INFO: CLIENT(37.228.253.250:49059): desired protocol magic '  V2'
[nsqd] 2020/04/27 17:47:09.571356 INFO: [37.228.253.250:49059] IDENTIFY: {ClientID:reyes Hostname:reyes HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.7 MsgTimeout:0}
[nsqd] 2020/04/27 17:47:09.974742 INFO: TOPIC(test): created
[nsqd] 2020/04/27 17:47:09.974815 INFO: CI: querying nsqlookupd http://nsqlookupd-02:9012/channels?topic=test
[nsqd] 2020/04/27 17:47:09.975346 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-01/nsqd.dat
[nsqd] 2020/04/27 17:47:09.975713 INFO: LOOKUPD(172.31.47.238:9001): topic REGISTER test
[nsqd] 2020/04/27 17:47:09.975984 INFO: LOOKUPD(172.31.47.238:9002): topic REGISTER test
[nsqd] 2020/04/27 17:47:09.976307 INFO: CI: querying nsqlookupd http://nsqlookupd-01:9011/channels?topic=test
[nsqd] 2020/04/27 17:47:09.994447 WARNING: failed to query nsqlookupd for channels to pre-create for topic test - Failed to query any nsqlookupd: Get http://nsqlookupd-01:9011/channels?topic=test: dial tcp: lookup nsqlookupd-01 on 127.0.0.53:53: server misbehaving
Get http://nsqlookupd-02:9012/channels?topic=test: dial tcp: lookup nsqlookupd-02 on 127.0.0.53:53: server misbehaving
[nsqd] 2020/04/27 17:47:09.994526 INFO: TOPIC(test): new channel(test)
[nsqd] 2020/04/27 17:47:09.994543 INFO: NSQ: persisting topic/channel metadata to /nsqd/nsqd-01/nsqd.dat
[nsqd] 2020/04/27 17:47:09.994938 INFO: LOOKUPD(172.31.47.238:9001): channel REGISTER test test
[nsqd] 2020/04/27 17:47:09.995213 INFO: LOOKUPD(172.31.47.238:9002): channel REGISTER test test
[nsqd] 2020/04/27 17:48:46.219415 INFO: 200 GET /stats?format=json&topic=test&include_clients=false (172.31.47.238:43672) 64.651µs
[nsqd] 2020/04/27 17:48:53.228774 INFO: 200 GET /stats?format=json&topic=test&include_clients=false (172.31.47.238:43672) 35.747µs
[nsqd] 2020/04/27 17:48:57.618931 INFO: 200 GET /stats?format=json (172.31.47.238:43672) 41.217µs
[nsqd] 2020/04/27 17:49:11.012672 INFO: 200 GET /stats?format=json&topic=test&include_clients=false (172.31.47.238:43672) 45.016µs
[nsqd] 2020/04/27 17:49:15.859609 INFO: 200 GET /stats?format=json (172.31.47.238:43672) 57.263µs
[nsqd] 2020/04/27 17:49:23.101264 INFO: PROTOCOL(V2): [37.228.253.250:49059] exiting ioloop
[nsqd] 2020/04/27 17:49:23.101397 INFO: PROTOCOL(V2): [37.228.253.250:49059] exiting messagePump
[nsqd] 2020/04/27 17:49:28.671500 INFO: 200 GET /stats?format=json (172.31.47.238:43672) 32.83µs
[nsqd] 2020/04/27 17:49:32.667576 INFO: 200 GET /stats?format=json&topic=test&include_clients=false (172.31.47.238:43672) 32.88µs
[nsqd] 2020/04/27 17:54:57.089914 INFO: TCP: new client(37.228.253.250:49065)
[nsqd] 2020/04/27 17:54:57.090093 INFO: CLIENT(37.228.253.250:49065): desired protocol magic '  V2'
[nsqd] 2020/04/27 17:54:57.095987 INFO: [37.228.253.250:49065] IDENTIFY: {ClientID:reyes Hostname:reyes HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.7 MsgTimeout:0}
[nsqd] 2020/04/27 17:55:03.017300 INFO: PROTOCOL(V2): [37.228.253.250:49065] exiting ioloop
[nsqd] 2020/04/27 17:55:03.017449 INFO: PROTOCOL(V2): [37.228.253.250:49065] exiting messagePump
[nsqd] 2020/04/28 09:39:00.445755 INFO: TCP: new client(37.228.253.250:49064)
[nsqd] 2020/04/28 09:39:00.453692 INFO: CLIENT(37.228.253.250:49064): desired protocol magic '  V2'
[nsqd] 2020/04/28 09:39:00.453845 INFO: [37.228.253.250:49064] IDENTIFY: {ClientID:reyes Hostname:reyes HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.7 MsgTimeout:0}
[nsqd] 2020/04/28 09:39:05.923430 INFO: PROTOCOL(V2): [37.228.253.250:49064] exiting ioloop
[nsqd] 2020/04/28 09:39:05.923581 INFO: PROTOCOL(V2): [37.228.253.250:49064] exiting messagePump
[nsqd] 2020/04/28 10:58:03.885694 INFO: TCP: new client(37.228.253.250:49020)
[nsqd] 2020/04/28 10:58:03.891294 INFO: CLIENT(37.228.253.250:49020): desired protocol magic '  V2'
[nsqd] 2020/04/28 10:58:03.891451 INFO: [37.228.253.250:49020] IDENTIFY: {ClientID:reyes Hostname:reyes HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.7 MsgTimeout:0}
[nsqd] 2020/04/28 10:58:07.862204 INFO: PROTOCOL(V2): [37.228.253.250:49020] exiting ioloop
[nsqd] 2020/04/28 10:58:07.862358 INFO: PROTOCOL(V2): [37.228.253.250:49020] exiting messagePump
[nsqd] 2020/04/28 11:03:39.923406 INFO: TCP: new client(37.228.253.250:49129)
[nsqd] 2020/04/28 11:03:39.923514 INFO: CLIENT(37.228.253.250:49129): desired protocol magic '  V2'
[nsqd] 2020/04/28 11:03:39.923638 INFO: [37.228.253.250:49129] IDENTIFY: {ClientID:reyes Hostname:reyes HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.8 MsgTimeout:0}

@jreyeshdez
Copy link
Author

@jreyeshdez can you share the logs from the other daemons running (e.g. nsqd and nsqlookupd)

nsqlookupd logs: 
[nsqlookupd] 2020/04/27 16:52:54.237033 INFO: nsqlookupd v1.2.0 (built w/go1.12.9)
[nsqlookupd] 2020/04/27 16:52:54.238449 INFO: nsqlookupd v1.2.0 (built w/go1.12.9)
[nsqlookupd] 2020/04/27 16:52:54.242227 INFO: HTTP: listening on 172.31.47.238:9012
[nsqlookupd] 2020/04/27 16:52:54.242341 INFO: TCP: listening on 172.31.47.238:9002
[nsqlookupd] 2020/04/27 16:52:54.242413 INFO: HTTP: listening on 172.31.47.238:9011
[nsqlookupd] 2020/04/27 16:52:54.242439 INFO: TCP: listening on 172.31.47.238:9001
[nsqlookupd] 2020/04/27 16:52:54.264755 INFO: TCP: new client(172.31.47.238:44548)
[nsqlookupd] 2020/04/27 16:52:54.265081 INFO: CLIENT(172.31.47.238:44548): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.265395 INFO: CLIENT(172.31.47.238:44548): IDENTIFY Address:nsqd-01 TCP:9031 HTTP:9041 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.265415 INFO: DB: client(172.31.47.238:44548) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.265749 INFO: TCP: new client(172.31.47.238:38086)
[nsqlookupd] 2020/04/27 16:52:54.265874 INFO: CLIENT(172.31.47.238:38086): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.266138 INFO: CLIENT(172.31.47.238:38086): IDENTIFY Address:nsqd-01 TCP:9031 HTTP:9041 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.266156 INFO: DB: client(172.31.47.238:38086) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.284539 INFO: TCP: new client(172.31.47.238:44552)
[nsqlookupd] 2020/04/27 16:52:54.284676 INFO: CLIENT(172.31.47.238:44552): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.284929 INFO: CLIENT(172.31.47.238:44552): IDENTIFY Address:nsqd-03 TCP:9033 HTTP:9043 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.284945 INFO: DB: client(172.31.47.238:44552) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.285222 INFO: TCP: new client(172.31.47.238:38090)
[nsqlookupd] 2020/04/27 16:52:54.285317 INFO: CLIENT(172.31.47.238:38090): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.285545 INFO: CLIENT(172.31.47.238:38090): IDENTIFY Address:nsqd-03 TCP:9033 HTTP:9043 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.285559 INFO: DB: client(172.31.47.238:38090) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.287241 INFO: TCP: new client(172.31.47.238:44556)
[nsqlookupd] 2020/04/27 16:52:54.287399 INFO: CLIENT(172.31.47.238:44556): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.287691 INFO: CLIENT(172.31.47.238:44556): IDENTIFY Address:nsqd-02 TCP:9032 HTTP:9042 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.287705 INFO: DB: client(172.31.47.238:44556) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.287992 INFO: TCP: new client(172.31.47.238:38094)
[nsqlookupd] 2020/04/27 16:52:54.288099 INFO: CLIENT(172.31.47.238:38094): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.288313 INFO: CLIENT(172.31.47.238:38094): IDENTIFY Address:nsqd-02 TCP:9032 HTTP:9042 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.288326 INFO: DB: client(172.31.47.238:38094) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.297939 INFO: TCP: new client(172.31.47.238:44560)
[nsqlookupd] 2020/04/27 16:52:54.298088 INFO: CLIENT(172.31.47.238:44560): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.298333 INFO: CLIENT(172.31.47.238:44560): IDENTIFY Address:nsqd-04 TCP:9034 HTTP:9044 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.298348 INFO: DB: client(172.31.47.238:44560) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.298625 INFO: TCP: new client(172.31.47.238:38098)
[nsqlookupd] 2020/04/27 16:52:54.298721 INFO: CLIENT(172.31.47.238:38098): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.298948 INFO: CLIENT(172.31.47.238:38098): IDENTIFY Address:nsqd-04 TCP:9034 HTTP:9044 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.298962 INFO: DB: client(172.31.47.238:38098) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.306393 INFO: TCP: new client(172.31.47.238:44564)
[nsqlookupd] 2020/04/27 16:52:54.306542 INFO: CLIENT(172.31.47.238:44564): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.306772 INFO: CLIENT(172.31.47.238:44564): IDENTIFY Address:nsqd-05 TCP:9035 HTTP:9045 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.306786 INFO: DB: client(172.31.47.238:44564) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:52:54.307063 INFO: TCP: new client(172.31.47.238:38102)
[nsqlookupd] 2020/04/27 16:52:54.307164 INFO: CLIENT(172.31.47.238:38102): desired protocol magic '  V1'
[nsqlookupd] 2020/04/27 16:52:54.307356 INFO: CLIENT(172.31.47.238:38102): IDENTIFY Address:nsqd-05 TCP:9035 HTTP:9045 Version:1.2.0
[nsqlookupd] 2020/04/27 16:52:54.307368 INFO: DB: client(172.31.47.238:38102) REGISTER category:client key: subkey:
[nsqlookupd] 2020/04/27 16:53:09.264903 INFO: CLIENT(172.31.47.238:44548): pinged (last ping 14.999501375s)
[nsqlookupd] 2020/04/27 16:53:09.265099 INFO: CLIENT(172.31.47.238:38086): pinged (last ping 14.998959175s)
[nsqlookupd] 2020/04/27 16:53:09.284632 INFO: CLIENT(172.31.47.238:44552): pinged (last ping 14.999703892s)
[nsqlookupd] 2020/04/27 16:53:09.284776 INFO: CLIENT(172.31.47.238:38090): pinged (last ping 14.999232236s)
[nsqlookupd] 2020/04/27 16:53:09.287352 INFO: CLIENT(172.31.47.238:44556): pinged (last ping 14.999662041s)
[nsqlookupd] 2020/04/27 16:53:09.287478 INFO: CLIENT(172.31.47.238:38094): pinged (last ping 14.999165944s)
...
[nsqlookupd] 2020/04/27 16:56:24.306620 INFO: CLIENT(172.31.47.238:38102): pinged (last ping 15.000013783s)
[nsqlookupd] 2020/04/27 16:56:35.157869 INFO: 200 GET /topics (172.31.47.238:49868) 3.879µs
[nsqlookupd] 2020/04/27 16:56:35.157954 INFO: 200 GET /topics (172.31.47.238:58854) 2.32µs
[nsqlookupd] 2020/04/27 16:56:36.664983 INFO: 200 GET /topics (172.31.47.238:49868) 3.839µs
[nsqlookupd] 2020/04/27 16:56:36.665248 INFO: 200 GET /topics (172.31.47.238:58854) 2.49µs
[nsqlookupd] 2020/04/27 16:56:39.264842 INFO: CLIENT(172.31.47.238:44548): pinged (last ping 14.999855616s)
[nsqlookupd] 2020/04/27 16:56:39.265050 INFO: CLIENT(172.31.47.238:38086): pinged (last ping 14.999775233s)
[nsqlookupd] 2020/04/27 16:56:39.284619 INFO: CLIENT(172.31.47.238:44552): pinged (last ping 14.999981081s)
[nsqlookupd] 2020/04/27 16:56:39.284785 INFO: CLIENT(172.31.47.238:38090): pinged (last ping 15.000016076s)
[nsqlookupd] 2020/04/27 16:56:39.287295 INFO: CLIENT(172.31.47.238:44556): pinged (last ping 14.999996687s)
[nsqlookupd] 2020/04/27 16:56:39.287415 INFO: CLIENT(172.31.47.238:38094): pinged (last ping 14.999989719s)
[nsqlookupd] 2020/04/27 16:56:39.297901 INFO: CLIENT(172.31.47.238:44560): pinged (last ping 15.000002584s)
[nsqlookupd] 2020/04/27 16:56:39.298021 INFO: CLIENT(172.31.47.238:38098): pinged (last ping 14.998171098s)
[nsqlookupd] 2020/04/27 16:56:39.306538 INFO: CLIENT(172.31.47.238:44564): pinged (last ping 15.000047072s)
[nsqlookupd] 2020/04/27 16:56:39.306771 INFO: CLIENT(172.31.47.238:38102): pinged (last ping 15.000146515s)
[nsqlookupd] 2020/04/27 16:56:41.165546 INFO: 200 GET /nodes (172.31.47.238:58854) 48.888µs
[nsqlookupd] 2020/04/27 16:56:41.166099 INFO: 200 GET /nodes (172.31.47.238:49868) 861.115µs

@jreyeshdez
Copy link
Author

I was also able to reproduce the issue by setting up nsq via docker compose so you might get more valuable logs in there too.

@mreiferson mreiferson self-assigned this Jun 14, 2020
@mreiferson mreiferson removed their assignment Jan 1, 2021
@syz521
Copy link

syz521 commented Mar 30, 2021

You should connected to the nsqd to create topic

@hyhilman
Copy link

Any info on this one? I get this error as well. this happening when I change the port. when I use the default port I have no problem.

run command 
./nsqd --lookupd-tcp-address=0.0.0.0:4160 -broadcast-address privateip -tcp-address=0.0.0.0:41500 -log-level debug
./nsqlookupd -tcp-address 0.0.0.0:4160 -http-address 0.0.0.0:41611 -broadcast-address privateip -log-level debug
./nsqadmin -lookupd-http-address privateip:41611 -http-address 0.0.0.0:4171 -log-level debug

@mreiferson
Copy link
Member

From @jreyeshdez's logs, this stands out (from nsqd):

[nsqd] 2020/04/27 17:47:09.976307 INFO: CI: querying nsqlookupd http://nsqlookupd-01:9011/channels?topic=test
[nsqd] 2020/04/27 17:47:09.994447 WARNING: failed to query nsqlookupd for channels to pre-create for topic test - Failed to query any nsqlookupd: Get http://nsqlookupd-01:9011/channels?topic=test: dial tcp: lookup nsqlookupd-01 on 127.0.0.53:53: server misbehaving
Get http://nsqlookupd-02:9012/channels?topic=test: dial tcp: lookup nsqlookupd-02 on 127.0.0.53:53: server misbehaving
[nsqd] 2020/04/27 17:47:09.994526 INFO: TOPIC(test): new channel(test)

It looks like there's at least some DNS oddness going on (it's always DNS).

Also, the logs I'm looking for are from boot through manual topic creation, without consumers connecting.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@mreiferson @ploxiln @jreyeshdez @hyhilman @syz521