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

nsqd: client error logged even when cleanly closed #521

Closed
detailyang opened this issue Jan 8, 2015 · 24 comments
Closed

nsqd: client error logged even when cleanly closed #521

detailyang opened this issue Jan 8, 2015 · 24 comments

Comments

@detailyang
Copy link

nsqd always print log as follow on our production environment:

[nsqd] 2015/01/08 22:49:51.130538 TCP: new client(10.6.28.53:22505)
[nsqd] 2015/01/08 22:49:51.130847 CLIENT(10.6.28.53:22505): desired protocol magic '  V2'
[nsqd] 2015/01/08 22:49:51.137175 PROTOCOL(V2): [10.6.28.53:22505] exiting ioloop
[nsqd] 2015/01/08 22:49:51.137273 ERROR: client(10.6.28.53:22505) - failed to read command - EOF
[nsqd] 2015/01/08 22:49:51.137310 PROTOCOL(V2): [10.6.28.53:22505] exiting messagePump

my environment like this:

CentOS release 6.6 (Final)                                                                                                 
Kernel \r on an \m                                                                                                
2.6.32-504.3.3.el6.x86_64
nsqd v0.3.0 (built w/go1.3.3)

and my nsq client used nsqphp

so, Any idea?

@mreiferson
Copy link
Member

Can you paste code?

You can turn nsqd debug mode on to see what the client is sending, too.

P.S. This issue probably belongs on the nsqphp repo, though.

@detailyang
Copy link
Author

hi, i found this error reported by func (*Reader) ReadSlice

func (*Reader) ReadSlice

func (b *Reader) ReadSlice(delim byte) (line []byte, err error)
ReadSlice reads until the first occurrence of delim in the input, returning a slice pointing at the bytes in the buffer. The bytes stop being valid at the next read. If ReadSlice encounters an error before finding a delimiter, it returns all the data in the buffer and the error itself (often io.EOF). ReadSlice fails with error ErrBufferFull if the buffer fills without a delim. Because the data returned from ReadSlice will be overwritten by the next I/O operation, most clients should use ReadBytes or ReadString instead. ReadSlice returns err != nil if and only if line does not end in delim.
So it means there are not '\n' in Reader
https://github.com/bitly/nsq/blob/master/nsqd/protocol_v2.go#62
line, err = client.Reader.ReadSlice('\n')
        if err != nil {
            err = fmt.Errorf("failed to read command - %s", err)
            break

I'm not familiar with Go:(
And finally, how to turn nsqd debug mode? i cannot found nsqd --help with debug, only verbose=true.

@mreiferson
Copy link
Member

Right, this is most likely an issue with nsqphp and not nsqd itself (which is why I mentioned this might not be the best place for this issue).

Yes, I meant --verbose not "debug", sorry!

@detailyang
Copy link
Author

[nsqd] 2015/01/08 23:20:17.663770 TCP: new client(10.6.19.252:30663)
[nsqd] 2015/01/08 23:20:17.664059 CLIENT(10.6.19.252:30663): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:17.665690 PROTOCOL(V2): [10.6.19.252:30663] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:17.673172 PROTOCOL(V2): [10.6.19.252:30663] exiting ioloop
[nsqd] 2015/01/08 23:20:17.673257 ERROR: client(10.6.19.252:30663) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:17.673281 PROTOCOL(V2): [10.6.19.252:30663] exiting messagePump
[nsqd] 2015/01/08 23:20:18.082931 TCP: new client(10.6.13.136:41491)
[nsqd] 2015/01/08 23:20:18.083272 CLIENT(10.6.13.136:41491): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.084410 PROTOCOL(V2): [10.6.13.136:41491] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:18.133459 PROTOCOL(V2): [10.6.13.136:41491] exiting ioloop
[nsqd] 2015/01/08 23:20:18.133675 ERROR: client(10.6.13.136:41491) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.133722 PROTOCOL(V2): [10.6.13.136:41491] exiting messagePump
[nsqd] 2015/01/08 23:20:18.160100 TCP: new client(10.6.13.136:41518)
[nsqd] 2015/01/08 23:20:18.160515 CLIENT(10.6.13.136:41518): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.161307 PROTOCOL(V2): [10.6.13.136:41518] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:18.165658 PROTOCOL(V2): [10.6.13.136:41518] exiting ioloop
[nsqd] 2015/01/08 23:20:18.165746 ERROR: client(10.6.13.136:41518) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.165773 PROTOCOL(V2): [10.6.13.136:41518] exiting messagePump
[nsqd] 2015/01/08 23:20:18.227671 TCP: new client(10.6.4.226:58895)
[nsqd] 2015/01/08 23:20:18.227975 CLIENT(10.6.4.226:58895): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.228806 PROTOCOL(V2): [10.6.4.226:58895] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:18.234188 PROTOCOL(V2): [10.6.4.226:58895] exiting ioloop
[nsqd] 2015/01/08 23:20:18.234282 ERROR: client(10.6.4.226:58895) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.234306 PROTOCOL(V2): [10.6.4.226:58895] exiting messagePump
[nsqd] 2015/01/08 23:20:18.295425 TCP: new client(10.6.8.135:18553)
[nsqd] 2015/01/08 23:20:18.295574 CLIENT(10.6.8.135:18553): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.296290 PROTOCOL(V2): [10.6.8.135:18553] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:18.300544 PROTOCOL(V2): [10.6.8.135:18553] exiting ioloop
[nsqd] 2015/01/08 23:20:18.300618 ERROR: client(10.6.8.135:18553) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.300648 PROTOCOL(V2): [10.6.8.135:18553] exiting messagePump
[nsqd] 2015/01/08 23:20:18.349784 PROTOCOL(V2): [10.6.6.220:62043] exiting ioloop
[nsqd] 2015/01/08 23:20:18.349924 ERROR: client(10.6.6.220:62043) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.349982 PROTOCOL(V2): [10.6.6.220:62043] exiting messagePump
[nsqd] 2015/01/08 23:20:18.355661 TCP: new client(10.6.6.220:11851)
[nsqd] 2015/01/08 23:20:18.356137 CLIENT(10.6.6.220:11851): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.441311 TCP: new client(10.6.4.226:58970)
[nsqd] 2015/01/08 23:20:18.441988 CLIENT(10.6.4.226:58970): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.442823 PROTOCOL(V2): [10.6.4.226:58970] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:18.447719 PROTOCOL(V2): [10.6.4.226:58970] exiting ioloop
[nsqd] 2015/01/08 23:20:18.447782 ERROR: client(10.6.4.226:58970) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.447802 PROTOCOL(V2): [10.6.4.226:58970] exiting messagePump
[nsqd] 2015/01/08 23:20:18.569500 TCP: new client(10.6.19.252:30932)
[nsqd] 2015/01/08 23:20:18.569832 CLIENT(10.6.19.252:30932): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.570673 PROTOCOL(V2): [10.6.19.252:30932] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:18.621603 TCP: new client(10.6.8.135:18661)
[nsqd] 2015/01/08 23:20:18.621822 CLIENT(10.6.8.135:18661): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.622573 PROTOCOL(V2): [10.6.8.135:18661] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:18.623866 PROTOCOL(V2): [10.6.19.252:30932] exiting ioloop
[nsqd] 2015/01/08 23:20:18.623976 ERROR: client(10.6.19.252:30932) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.624051 PROTOCOL(V2): [10.6.19.252:30932] exiting messagePump
[nsqd] 2015/01/08 23:20:18.626240 PROTOCOL(V2): [10.6.8.135:18661] exiting ioloop
[nsqd] 2015/01/08 23:20:18.626322 ERROR: client(10.6.8.135:18661) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:18.626352 PROTOCOL(V2): [10.6.8.135:18661] exiting messagePump
[nsqd] 2015/01/08 23:20:18.893977 TCP: new client(10.6.4.226:59131)
[nsqd] 2015/01/08 23:20:18.894669 CLIENT(10.6.4.226:59131): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:18.895462 PROTOCOL(V2): [10.6.4.226:59131] [PUB task_team]
[nsqd] 2015/01/08 23:20:18.922953 [10.6.5.28:52503] state rdy:    1 inflt:    0
[nsqd] 2015/01/08 23:20:18.924421 PROTOCOL(V2): [10.6.5.28:52503] [NOP]
[nsqd] 2015/01/08 23:20:19.010028 TCP: new client(10.6.19.252:31089)
[nsqd] 2015/01/08 23:20:19.010655 CLIENT(10.6.19.252:31089): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.011576 PROTOCOL(V2): [10.6.19.252:31089] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:19.017636 PROTOCOL(V2): [10.6.19.252:31089] exiting ioloop
[nsqd] 2015/01/08 23:20:19.017716 ERROR: client(10.6.19.252:31089) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.017761 PROTOCOL(V2): [10.6.19.252:31089] exiting messagePump
[nsqd] 2015/01/08 23:20:19.090929 PROTOCOL(V2): [10.6.4.226:59131] exiting ioloop
[nsqd] 2015/01/08 23:20:19.091211 ERROR: client(10.6.4.226:59131) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.091260 PROTOCOL(V2): [10.6.4.226:59131] exiting messagePump
[nsqd] 2015/01/08 23:20:19.109322 PROTOCOL(V2): [10.6.5.28:47995] [RDY 0]
[nsqd] 2015/01/08 23:20:19.109421 [10.6.5.28:47995] state rdy:    0 inflt:    0
[nsqd] 2015/01/08 23:20:19.110062 PROTOCOL(V2): [10.6.5.28:47995] [RDY 1]
[nsqd] 2015/01/08 23:20:19.110123 [10.6.5.28:47995] state rdy:    1 inflt:    0
[nsqd] 2015/01/08 23:20:19.802849 TCP: new client(10.6.28.53:15224)
[nsqd] 2015/01/08 23:20:19.803009 CLIENT(10.6.28.53:15224): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.803373 TCP: new client(10.6.7.97:48141)
[nsqd] 2015/01/08 23:20:19.803710 PROTOCOL(V2): [10.6.28.53:15224] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:19.804985 CLIENT(10.6.7.97:48141): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.806035 PROTOCOL(V2): [10.6.7.97:48141] [PUB task_team]
[nsqd] 2015/01/08 23:20:19.810453 PROTOCOL(V2): [10.6.7.97:48141] exiting ioloop
[nsqd] 2015/01/08 23:20:19.810596 ERROR: client(10.6.7.97:48141) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.810645 PROTOCOL(V2): [10.6.7.97:48141] exiting messagePump
[nsqd] 2015/01/08 23:20:19.816316 TCP: new client(10.6.12.191:16640)
[nsqd] 2015/01/08 23:20:19.816741 CLIENT(10.6.12.191:16640): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.817462 PROTOCOL(V2): [10.6.12.191:16640] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:19.883738 PROTOCOL(V2): [10.6.12.191:16640] exiting ioloop
[nsqd] 2015/01/08 23:20:19.883890 ERROR: client(10.6.12.191:16640) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.883919 PROTOCOL(V2): [10.6.12.191:16640] exiting messagePump
[nsqd] 2015/01/08 23:20:19.894080 PROTOCOL(V2): [10.6.28.53:15224] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:19.899098 PROTOCOL(V2): [10.6.28.53:15224] exiting ioloop
[nsqd] 2015/01/08 23:20:19.899189 ERROR: client(10.6.28.53:15224) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.899234 PROTOCOL(V2): [10.6.28.53:15224] exiting messagePump
[nsqd] 2015/01/08 23:20:19.929490 TCP: new client(10.6.13.136:42144)
[nsqd] 2015/01/08 23:20:19.929680 CLIENT(10.6.13.136:42144): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.930573 PROTOCOL(V2): [10.6.13.136:42144] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:19.934336 TCP: new client(10.6.21.65:48076)
[nsqd] 2015/01/08 23:20:19.934629 CLIENT(10.6.21.65:48076): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:19.935383 PROTOCOL(V2): [10.6.21.65:48076] [PUB fans_info_normal]
[nsqd] 2015/01/08 23:20:19.936151 PROTOCOL(V2): [10.6.13.136:42144] exiting ioloop
[nsqd] 2015/01/08 23:20:19.936254 ERROR: client(10.6.13.136:42144) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.936303 PROTOCOL(V2): [10.6.13.136:42144] exiting messagePump
[nsqd] 2015/01/08 23:20:19.942512 PROTOCOL(V2): [10.6.21.65:48076] exiting ioloop
[nsqd] 2015/01/08 23:20:19.942598 ERROR: client(10.6.21.65:48076) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:19.942621 PROTOCOL(V2): [10.6.21.65:48076] exiting messagePump
[nsqd] 2015/01/08 23:20:20.112015 TCP: new client(10.6.5.67:34382)
[nsqd] 2015/01/08 23:20:20.112331 CLIENT(10.6.5.67:34382): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:20.113278 PROTOCOL(V2): [10.6.5.67:34382] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:20.119793 PROTOCOL(V2): [10.6.5.67:34382] exiting ioloop
[nsqd] 2015/01/08 23:20:20.119882 ERROR: client(10.6.5.67:34382) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:20.119925 PROTOCOL(V2): [10.6.5.67:34382] exiting messagePump
[nsqd] 2015/01/08 23:20:20.233710 TCP: new client(10.6.8.135:19224)
[nsqd] 2015/01/08 23:20:20.233943 CLIENT(10.6.8.135:19224): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:20.234649 PROTOCOL(V2): [10.6.8.135:19224] [PUB task_team]
[nsqd] 2015/01/08 23:20:20.237349 PROTOCOL(V2): [10.6.8.135:19224] exiting ioloop
[nsqd] 2015/01/08 23:20:20.237443 ERROR: client(10.6.8.135:19224) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:20.237653 PROTOCOL(V2): [10.6.8.135:19224] exiting messagePump
[nsqd] 2015/01/08 23:20:20.448912 TCP: new client(10.6.12.191:16887)
[nsqd] 2015/01/08 23:20:20.449053 CLIENT(10.6.12.191:16887): desired protocol magic '  V2'
[nsqd] 2015/01/08 23:20:20.450155 PROTOCOL(V2): [10.6.12.191:16887] [PUB msg_pool_forward]
[nsqd] 2015/01/08 23:20:20.457084 PROTOCOL(V2): [10.6.12.191:16887] exiting ioloop
[nsqd] 2015/01/08 23:20:20.458083 ERROR: client(10.6.12.191:16887) - failed to read command - EOF
[nsqd] 2015/01/08 23:20:20.458124 PROTOCOL(V2): [10.6.12.191:16887] exiting messagePump
[nsqd] 2015/01/08 23:20:20.461604 PROTOCOL(V2): [10.6.5.28:49277] [RDY 1]
[nsqd] 2015/01/08 23:20:20.461734 [10.6.5.28:49277] state rdy:    1 inflt:    0

in fact , i guess it's not about nsq and nsqphp, maybe it's about network.This problem happening on when i move nsqd to new Server Room.
we run the same code on two Server Room and 'failed to read command ' only happend on old machine.
so i should check the system network configure and thx for reply:)

@detailyang
Copy link
Author

hi, i used tcpdump to dump some tcp package to local, so can you find anything?

@detailyang detailyang reopened this Jan 8, 2015
@stephensearles
Copy link

So you might be running into the same issue I did. Are you using nsqphp for publishing only? If so, take a look at the changes here: davegardnerisme/nsqphp#33

If you're only publishing, nsqphp doesn't attempt to read heartbeats and that gets its reading of the connection in an odd state. If this is what's causing your issue, that PR might solve it for you.

@detailyang
Copy link
Author

@stephensearles , i merge your pull request and it's unhelpful:(

@tj
Copy link
Contributor

tj commented Jan 22, 2015

FWIW I get this consistently via go-nsq, latest of both packages, just using defaults. I was looking into what I thought was my own bug with not stopping publishers properly but seems like it's easy to repro:

p, _ := nsq.NewProducer(":4150", nsq.NewConfig())
for i := 0; i < 10; i++ {
    p.Publish("something", []byte("foo"))
}
p.Stop()

@mreiferson
Copy link
Member

yea, that's also a go-nsq issue. Producer should be using the "clean close" flow that Consumer uses, instead it's just closing the connection, causing that error.

I'm gonna close this as I think they're client library issues... I'm going to open one for go-nsq now.

@jothirams
Copy link

@mreiferson

I’m trying out the go-nsq and I see that with consumer the clean-close (CLS is sent) is happening, but still the "failed to read command - EOF" is printed. Is it still a client library issue or nsqd?

My logs: from consumer

^C
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] stopping...
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) received CLOSE_WAIT from nsqd
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) beginning close
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) readLoop exiting
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) breaking out of writeLoop
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) writeLoop exiting
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) finished draining, cleanup exiting
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] (localhost:4150) clean close complete
2015/02/11 16:53:46 WRN    1 [TestTopic/TestChannel] there are 0 connections left alive
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] stopping handlers
2015/02/11 16:53:46 INF    1 [TestTopic/TestChannel] rdyLoop exiting

From nsqd --verbose:

[nsqd] 2015/02/11 16:53:36.647884 PROTOCOL(V2): [127.0.0.1:61943] [SUB TestTopic TestChannel]
[nsqd] 2015/02/11 16:53:36.649635 TOPIC(TestTopic): created
[nsqd] 2015/02/11 16:53:36.649675 NSQ: persisting topic/channel metadata to nsqd.1011.dat
[nsqd] 2015/02/11 16:53:36.650014 TOPIC(TestTopic): new channel(TestChannel)
[nsqd] 2015/02/11 16:53:36.650092 PROTOCOL(V2): [127.0.0.1:61943] [RDY 25]
[nsqd] 2015/02/11 16:53:36.650174 [127.0.0.1:61943] state rdy:   25 inflt:    0
[nsqd] 2015/02/11 16:53:36.650572 NSQ: persisting topic/channel metadata to nsqd.1011.dat



[nsqd] 2015/02/11 16:53:46.863715 PROTOCOL(V2): [127.0.0.1:61943] [CLS]
[nsqd] 2015/02/11 16:53:46.863800 [127.0.0.1:61943] state rdy:    0 inflt:    0
[nsqd] 2015/02/11 16:53:46.966696 PROTOCOL(V2): [127.0.0.1:61943] exiting ioloop
[nsqd] 2015/02/11 16:53:46.966853 ERROR: client(127.0.0.1:61943) - failed to read command - EOF
[nsqd] 2015/02/11 16:53:46.966898 PROTOCOL(V2): [127.0.0.1:61943] exiting messagePump

@mreiferson
Copy link
Member

Hmmm, ok, I suppose nsqd can do a better job of skipping that error message when it's already received a CLS.

@mreiferson mreiferson reopened this Feb 11, 2015
@mreiferson mreiferson changed the title failed to read command - EOF nsqd: failed to read command - EOF even when cleanly closed Feb 11, 2015
@mreiferson mreiferson changed the title nsqd: failed to read command - EOF even when cleanly closed nsqd: client error logged even when cleanly closed Feb 11, 2015
@jothirams
Copy link

Hi @mreiferson

Just to add, the go-nsq after it sends FINishing as well, I see the client failed to read command - EOF.

[nsqd] 2015/02/12 11:09:48.915132 [127.0.0.1:63343] state rdy:   25 inflt:    1
[nsqd] 2015/02/12 11:09:48.915427 [127.0.0.1:63343] state rdy:   25 inflt:    1
[nsqd] 2015/02/12 11:09:48.917056 PROTOCOL(V2): [127.0.0.1:63343] [FIN 07da2dbd147f3000]
[nsqd] 2015/02/12 11:09:48.917101 [127.0.0.1:63343] state rdy:   25 inflt:    0
[nsqd] 2015/02/12 11:09:50.110146 PROTOCOL(V2): [127.0.0.1:63346] exiting ioloop
[nsqd] 2015/02/12 11:09:50.110213 ERROR: client(127.0.0.1:63346) - failed to read command - EOF
[nsqd] 2015/02/12 11:09:50.110250 PROTOCOL(V2): [127.0.0.1:63346] exiting messagePump

@mreiferson
Copy link
Member

@jothirams I'm not sure I follow what situation you're describing, can you provide a reproducible test case, code, or commands I can run?

@jothirams
Copy link

@mreiferson The last comment that after FINishing as well, the failed to read command is being displayed is incorrect.

I was also using json-to-nsq and it was the problem that the go-nsq Producer was not doing a clean close. You can ignore this message.

However, the client when it still does a clean close the EOF error is seen.

@mreiferson
Copy link
Member

fixed in #560

@casertap
Copy link

+1
I think it is also related to this issue:
#560

I am following the instruction of this blog (it is very easy to reproduce): http://tleyden.github.io/blog/2014/11/12/an-example-of-using-nsq-from-go/

I get the same error.
here is my verbose trace:

vagrant@vagrant-ubuntu-trusty-64:~$ nsqd --verbose --lookupd-tcp-address=127.0.0.1:4160 &                     
[3] 2485
vagrant@vagrant-ubuntu-trusty-64:~$ [nsqd] 2015/09/25 13:29:13.940646 nsqd v0.3.5 (built w/go1.4.2)
[nsqd] 2015/09/25 13:29:13.941248 ID: 258
[nsqd] 2015/09/25 13:29:13.943995 TOPIC(votes): created
[nsqd] 2015/09/25 13:29:13.944763 DISKQUEUE(votes): readOne() opened votes.diskqueue.000000.dat
[nsqd] 2015/09/25 13:29:13.947648 TOPIC(write_test): created
[nsqd] 2015/09/25 13:29:13.947963 NSQ: persisting topic/channel metadata to nsqd.258.dat
[nsqd] 2015/09/25 13:29:13.947856 DISKQUEUE(write_test): readOne() opened write_test.diskqueue.000000.dat
[nsqd] 2015/09/25 13:29:13.950499 TCP: listening on [::]:4150
[nsqd] 2015/09/25 13:29:13.950940 HTTP: listening on [::]:4151                                                                                                                                     [13/1061]
[nsqd] 2015/09/25 13:29:13.952265 LOOKUP: adding peer 127.0.0.1:4160
[nsqd] 2015/09/25 13:29:13.953927 LOOKUP connecting to 127.0.0.1:4160
[nsqlookupd] 2015/09/25 13:29:13.957743 TCP: new client(127.0.0.1:57226)
[nsqlookupd] 2015/09/25 13:29:13.958545 CLIENT(127.0.0.1:57226): desired protocol magic '  V1'
[nsqlookupd] 2015/09/25 13:29:13.966164 CLIENT(127.0.0.1:57226): IDENTIFY Address:vagrant-ubuntu-trusty-64 TCP:4150 HTTP:4151 Version:0.3.5
[nsqlookupd] 2015/09/25 13:29:13.967096 DB: client(127.0.0.1:57226) REGISTER category:client key: subkey:
[nsqd] 2015/09/25 13:29:13.972373 LOOKUPD(127.0.0.1:4160): peer info {TCPPort:4160 HTTPPort:4161 Version:0.3.5 BroadcastAddress:vagrant-ubuntu-trusty-64}
[nsqd] 2015/09/25 13:29:13.973591 LOOKUPD(127.0.0.1:4160): topic REGISTER votes
[nsqlookupd] 2015/09/25 13:29:13.974467 DB: client(127.0.0.1:57226) REGISTER category:topic key:votes subkey:
[nsqd] 2015/09/25 13:29:13.974751 LOOKUPD(127.0.0.1:4160): topic REGISTER write_test
[nsqlookupd] 2015/09/25 13:29:13.975051 DB: client(127.0.0.1:57226) REGISTER category:topic key:write_test subkey:
[nsqd] 2015/09/25 13:29:13.975332 LOOKUPD(127.0.0.1:4160): REGISTER write_test
[nsqd] 2015/09/25 13:29:13.975628 LOOKUPD(127.0.0.1:4160): REGISTER votes                                                                                                                           [0/1061]
[nsqd] 2015/09/25 13:29:22.358399 TCP: new client(127.0.0.1:46688)
[nsqd] 2015/09/25 13:29:22.358428 CLIENT(127.0.0.1:46688): desired protocol magic '  V2'
[nsqd] 2015/09/25 13:29:22.360734 PROTOCOL(V2): [127.0.0.1:46688] [IDENTIFY]
[nsqd] 2015/09/25 13:29:22.362212 PROTOCOL(V2): [127.0.0.1:46688] {ShortID:vagrant-ubuntu-trusty-64 LongID:vagrant-ubuntu-trusty-64 ClientID:vagrant-ubuntu-trusty-64 Hostname:vagrant-ubuntu-trusty-64 Hear
tbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.5 MsgTimeout:0}
[nsqd] 2015/09/25 13:29:22.362558 [127.0.0.1:46688] IDENTIFY: {ShortID:vagrant-ubuntu-trusty-64 LongID:vagrant-ubuntu-trusty-64 ClientID:vagrant-ubuntu-trusty-64 Hostname:vagrant-ubuntu-trusty-64 Heartbea
tInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.5 MsgTimeout:0}
[nsqd] 2015/09/25 13:29:22.364152 PROTOCOL(V2): [127.0.0.1:46688] [PUB write_test]
[nsqd] 2015/09/25 13:29:22.366293 PROTOCOL(V2): [127.0.0.1:46688] exiting ioloop
[nsqd] 2015/09/25 13:29:22.366412 ERROR: client(127.0.0.1:46688) - failed to read command - EOF
[nsqd] 2015/09/25 13:29:22.366685 PROTOCOL(V2): [127.0.0.1:46688] exiting messagePump

nsqd v0.3.5 (built w/go1.4.2)
nsqlookupd v0.3.5 (built w/go1.4.2)
go version go1.4 linux/amd64
go-nsq version: "1.0.5"

@jehiah
Copy link
Member

jehiah commented Sep 25, 2015

@casertap the change in #560 (included in v0.3.5) only omitted that error when the client initiated a clean close (by sending a CLS message). That isn't the case in your example, but it's ok because #582 already changed that behavior to omit logging all EOF errors. That commit will be included in v0.3.6 which will be released shortly.

@casertap
Copy link

Thanks @jehiah.
Can you tell me what my go code should look like please?

@jehiah
Copy link
Member

jehiah commented Sep 25, 2015

@casertap I'm not quite sure what your question is beyond the EOF error in your log output. Can you start a thread on the nsq mailing list and folks can chime in to help you?

@casertap
Copy link

Of course. thanks

@maderaka
Copy link

Hi everyone.
So how to fix this problem? Please tell me specifically.
Sorry I'm new in Go and NSQ

Thanks

@jehiah
Copy link
Member

jehiah commented Oct 10, 2015

@maderaka can you provide information on what version you are running and the exact log output you are seeing?

@maderaka
Copy link

@jehiah That's already fixed.
But now, I have another issue. I will update later.
Thank you :)

@kant111
Copy link

kant111 commented Sep 2, 2016

@casertap I followed the same example from the same link as you and I get the same error as well. were you able to figure out how the code should look like in that example? If so, can you please forward it?

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

No branches or pull requests

9 participants