producer: unexpected io.EOF when calling Stop

[larzconwell]

We're calling Stop on a NSQ producer, and we're getting the following output after a number of MultiPublishes. Is this io.EOF error expected? We're using the tag 1.0.6.

INFO[0011] INF    1 stopping
INFO[0011] ERR    1 (127.0.0.1:4150) IO error - EOF
INFO[0011] INF    1 (127.0.0.1:4150) beginning close
INFO[0011] INF    1 (127.0.0.1:4150) readLoop exiting

[mreiferson]

I thought I remembered an old issue related to this but I can't seem to find one.

Looking at the code, we trap "closed connection" errors (ones that we expect would be the direct result of calling producer.Stop() which calls conn.Close()), but this is reporting EOF which is unexpected.

Can you provide a simplified reproducible test case?

[larzconwell]

Yeah io.EOF seemed very unexpected to us as well looking at the code. I linked the test case we're doing below, but it's not very deterministic. If you can't get it to error, try playing around with the message size or the number of batches.

https://gist.github.com/larzconwell/767daa616e4718dc2d4bc0b3e4495599

[mreiferson]

@larzconwell you're using an old import in that example bitly/go-nsq?

[mreiferson]

I can't reproduce using your example with the fixed import path and latest of go-nsq:

[mreiferson@AIRSNAKES ~/dev/src/github.com/nsqio/test]$ ./test 
2016/07/24 09:40:17 INF    1 (127.0.0.1:4150) connecting to nsqd
2016/07/24 09:40:19 INF    1 stopping
2016/07/24 09:40:19 INF    1 exiting router
[mreiferson@AIRSNAKES ~/dev/src/github.com/nsqio/test]$ ./test 
2016/07/24 09:40:25 INF    1 (127.0.0.1:4150) connecting to nsqd
2016/07/24 09:40:26 INF    1 stopping
2016/07/24 09:40:26 INF    1 exiting router
[mreiferson@AIRSNAKES ~/dev/src/github.com/nsqio/test]$ ./test 
2016/07/24 09:40:27 INF    1 (127.0.0.1:4150) connecting to nsqd
2016/07/24 09:40:28 INF    1 stopping
2016/07/24 09:40:28 INF    1 exiting router

[mreiferson@AIRSNAKES ~/dev/src/github.com/nsqio/test]$ nsqd
[nsqd] 2016/07/24 09:40:11.955123 nsqd v0.3.7 (built w/go1.6)
[nsqd] 2016/07/24 09:40:11.955539 ID: 292
[nsqd] 2016/07/24 09:40:11.955612 NSQ: persisting topic/channel metadata to nsqd.292.dat
[nsqd] 2016/07/24 09:40:11.970656 HTTP: listening on [::]:4151
[nsqd] 2016/07/24 09:40:11.970713 TCP: listening on [::]:4150
[nsqd] 2016/07/24 09:40:17.763954 TCP: new client(127.0.0.1:57801)
[nsqd] 2016/07/24 09:40:17.764584 CLIENT(127.0.0.1:57801): desired protocol magic '  V2'
[nsqd] 2016/07/24 09:40:17.770425 [127.0.0.1:57801] IDENTIFY: {ShortID:AIRSNAKES LongID:AIRSNAKES.local ClientID:AIRSNAKES Hostname:AIRSNAKES.local HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.6 MsgTimeout:0}
[nsqd] 2016/07/24 09:40:17.902409 TOPIC(ex_topic): created
[nsqd] 2016/07/24 09:40:17.902931 NSQ: persisting topic/channel metadata to nsqd.292.dat
[nsqd] 2016/07/24 09:40:17.959093 DISKQUEUE(ex_topic): writeOne() opened ex_topic.diskqueue.000000.dat
[nsqd] 2016/07/24 09:40:17.959259 DISKQUEUE(ex_topic): readOne() opened ex_topic.diskqueue.000000.dat
[nsqd] 2016/07/24 09:40:19.198556 PROTOCOL(V2): [127.0.0.1:57801] exiting ioloop
[nsqd] 2016/07/24 09:40:19.198705 PROTOCOL(V2): [127.0.0.1:57801] exiting messagePump
[nsqd] 2016/07/24 09:40:25.187188 TCP: new client(127.0.0.1:57805)
[nsqd] 2016/07/24 09:40:25.187219 CLIENT(127.0.0.1:57805): desired protocol magic '  V2'
[nsqd] 2016/07/24 09:40:25.187414 [127.0.0.1:57805] IDENTIFY: {ShortID:AIRSNAKES LongID:AIRSNAKES.local ClientID:AIRSNAKES Hostname:AIRSNAKES.local HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.6 MsgTimeout:0}
[nsqd] 2016/07/24 09:40:26.579470 PROTOCOL(V2): [127.0.0.1:57805] exiting ioloop
[nsqd] 2016/07/24 09:40:26.579609 PROTOCOL(V2): [127.0.0.1:57805] exiting messagePump
[nsqd] 2016/07/24 09:40:27.649063 TCP: new client(127.0.0.1:57808)
[nsqd] 2016/07/24 09:40:27.649093 CLIENT(127.0.0.1:57808): desired protocol magic '  V2'
[nsqd] 2016/07/24 09:40:27.650648 [127.0.0.1:57808] IDENTIFY: {ShortID:AIRSNAKES LongID:AIRSNAKES.local ClientID:AIRSNAKES Hostname:AIRSNAKES.local HeartbeatInterval:30000 OutputBufferSize:16384 OutputBufferTimeout:250 FeatureNegotiation:true TLSv1:false Deflate:false DeflateLevel:6 Snappy:false SampleRate:0 UserAgent:go-nsq/1.0.6 MsgTimeout:0}
[nsqd] 2016/07/24 09:40:28.956069 PROTOCOL(V2): [127.0.0.1:57808] exiting ioloop
[nsqd] 2016/07/24 09:40:28.956185 PROTOCOL(V2): [127.0.0.1:57808] exiting messagePump

[larzconwell]

Oh yes we are currently using an old version, but I tested it again with the latest at this repo and I'm still getting it. Though I'll say the messages are being sent and everything seems correct.

Looking into it more, the error is occurring here. Maybe it should check if EOF as well as closed network connection?

[variablebug]

+1

@mreiferson i think may be error logs does not printed all. so try add 'time.Sleep(time.Second * 3)' see below :

//.....

    wg.Add(batches)
    for i := 0; i < batches; i++ {
        go func() {
            defer wg.Done()

            err = producer.MultiPublish(topic, messages)
            if err != nil {
                log.Println(err)
            }
        }()
    }
    wg.Wait()
    producer.Stop()

    time.Sleep(time.Second * 3)  // wait error logs!!!!

2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) connecting to nsqd
2016/09/29 15:39:23 INF    1 stopping
2016/09/29 15:39:23 INF    1 exiting router
2016/09/29 15:39:23 ERR    1 (10.20.133.15:4150) IO error - EOF
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) beginning close
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) readLoop exiting
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) breaking out of writeLoop
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) writeLoop exiting
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) clean close complete
2016/09/29 15:39:23 INF    1 (10.20.133.15:4150) finished draining, cleanup exiting

[CodingMinds]

Any updates on this issue ?
We use the current master from go-nsq and see the same error message

2017/04/08 13:03:42 ERR    2 (127.0.0.1:4150) IO error - EOF
2017/04/08 13:03:42 INF    2 (127.0.0.1:4150) beginning close
2017/04/08 13:03:42 INF    2 (127.0.0.1:4150) readLoop exiting
2017/04/08 13:03:42 INF    2 (127.0.0.1:4150) breaking out of writeLoop
2017/04/08 13:03:42 INF    2 (127.0.0.1:4150) writeLoop exiting

[mreiferson]

Still need a reproducible test case...

[CodingMinds]

Does this help ?

Standalone example: https://gist.github.com/CodingMinds/e764f8c5c0d256b49251bb2cdf589de4
Embedded in producer_test.go: CodingMinds@1f4182b

[mreiferson]

fixed in #201, sorry for the delay!

[askie]

nsqd v1.1.0 (built w/go1.10.3)
error:

stopping
exiting router
IO error - EOF
beginning close
readLoop exiting
breaking out of writeLoop
writeLoop exiting
finished draining, cleanup exiting
clean close complete