Error connecting with python client lib 0.6.0

[Joe Francia]

I’m getting the following error when trying to connect to an NSQ server with the Python client lib: 'E_BAD_BODY IDENTIFY heartbeat interval (30) is invalid'. If I change the heartbeat to another value (e.g., 5), then the error changes to reflect that ('E_BAD_BODY IDENTIFY heartbeat interval (5) is invalid’). It seems the offending code is in "client_v2.go:267-277". It looks like any value > 0 and < 1000 falls through the switch and returns an error, so a case statement for values > 0 and < 1000 should probably be added.

	switch {
	case desiredInterval == -1:
		interval = -1
	case desiredInterval == 0:
		// do nothing (use default)
	case desiredInterval >= 1000 &&
		desiredInterval <= int(c.context.nsqd.options.MaxHeartbeatInterval/time.Millisecond):
		interval = (time.Duration(desiredInterval) * time.Millisecond)
	default:
		return errors.New(fmt.Sprintf("heartbeat interval (%d) is invalid", desiredInterval))
	}

Also, when I use 0 as the heartbeat_interval, the client library throws an AssertionError because it doesn't like the 0. And interestingly, if you set the heartbeat_interval to 1000 or higher, you get this error from the client lib:

—————————————— 

ERROR:root:uncaught exception in data event

Traceback (most recent call last):

  File "/<DELETED>/lib/python2.7/site-packages/nsq/async.py", line 183, in _read_body

    self.trigger('data', conn=self, data=data)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/evented_mixin.py", line 59, in trigger

    ev(*args, **kwargs)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/async.py", line 320, in _on_data

    self.trigger('response', conn=self, data=data)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/evented_mixin.py", line 59, in trigger

    ev(*args, **kwargs)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/async.py", line 279, in _on_identify_response

    self.trigger('identify_response', conn=self, data=data)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/evented_mixin.py", line 59, in trigger

    ev(*args, **kwargs)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/client.py", line 16, in _on_connection_identify_response

    if self.tls_v1 and not data.get('tls_v1'):

AttributeError: 'Reader' object has no attribute 'tls_v1'

—————————————— 

My setup and output looks like so:

• NSQ 0.2.26.darwin-amd64.go1.2
  
• ./nsqlookupd
  
• ./nsqd --lookupd-tcp-address=127.0.0.1:4160
  
• Python is 2.7.6
  
• pynsq is v0.6.0
  
• tornado is v3.2
  
• simplejson v3.3.3
  
• pushing message like so: "curl -d 'hello world 1' 'http://127.0.0.1:4151/put?topic=test"

———— test_client.py ————
import nsq

def process_message(message):
     print message

r = nsq.Reader(topic="test", channel="test_channel1", message_handler=process_message,
               lookupd_http_addresses=['http://127.0.0.1:4161'])
nsq.run()
—————————————— 


———— test_client.py output ————
ERROR:root:[monkeybrain:4150:test:test_channel1] ERROR: Error('E_BAD_BODY IDENTIFY heartbeat interval (30) is invalid',)
ERROR:tornado.application:Exception in callback <functools.partial object at 0x10a46daa0>
Traceback (most recent call last):
  File "/<DELETED>/lib/python2.7/site-packages/tornado/ioloop.py", line 477, in _run_callback
    callback()
  File "/<DELETED>/lib/python2.7/site-packages/tornado/stack_context.py", line 331, in wrapped
    raise_exc_info(exc)
  File "/<DELETED>/lib/python2.7/site-packages/tornado/stack_context.py", line 302, in wrapped
    ret = fn(*args, **kwargs)
  File "/<DELETED>/lib/python2.7/site-packages/nsq/async.py", line 164, in _start_read
    self.stream.read_bytes(4, self._read_size)
  File "/<DELETED>/lib/python2.7/site-packages/tornado/iostream.py", line 177, in read_bytes
    self._try_inline_read()
  File "/<DELETED>/lib/python2.7/site-packages/tornado/iostream.py", line 431, in _try_inline_read
    self._check_closed()
  File "/<DELETED>/lib/python2.7/site-packages/tornado/iostream.py", line 593, in _check_closed
    raise StreamClosedError("Stream is closed")
StreamClosedError: Stream is closed
WARNING:root:[monkeybrain:4150:test:test_channel1] connection closed
——————————————————


———— nsqd console ————- 
2014/02/15 19:22:28 TCP: new client(192.168.1.46:65162)
2014/02/15 19:22:28 CLIENT(192.168.1.46:65162): desired protocol magic '  V2'
2014/02/15 19:22:28 ERROR: [192.168.1.46:65162] - E_BAD_BODY IDENTIFY heartbeat interval (30) is invalid - heartbeat interval (30) is invalid
2014/02/15 19:22:28 PROTOCOL(V2): [192.168.1.46:65162] exiting ioloop
2014/02/15 19:22:28 PROTOCOL(V2): [192.168.1.46:65162] exiting messagePump
———————————————    

[Jehiah Czebotar]

Hi Joe. Thanks for the email. Looks like you've uncovered two pynsq issues.

The first is that nsqd is expecting millisecond values from the
client, but pynsq (due to recent refactoring) was sending it's default
value in terms of seconds. The nsqd check to exclude values 1-1000 was
specifically designed to catch that and enforce that a client didn't
ask for a heartbeat interval of 30milliseconds when they meant 30
seconds (yay that worked). Unfortunately the code doesn't make it very
clear what we intended by that check.

All that to say, i opened up a fix for pynsq sending 30(seconds)
instead of 30000(milliseconds) https://github.com/bitly/pynsq/pull/63

The second issue, (once you used a value in the >1000 millisecond
range) exposed a regression that was introduced by some previous
refactoring. I've added that to the same pull request for now.

If you are in a position to install pynsq from source and validate
that change i'd appreciate it.

You also stumbled across that the pynsq client doesn't allow you to
send -1 to disable heartbeats. I'll get that addressed separately.

--
Jehiah

[Joe Francia]

OK, Jehiah, that fixed the heartbeat and connection issue. Nice! However, now when I post a message using curl (as above), this is what my test client (as above) gives me:

<nsq.message.Message object at 0x110f06b90>

ERROR:root:[monkeybrain:4150:test:test_channel1] failed to handle_message() <nsq.message.Message object at 0x110f06b90>

Traceback (most recent call last):

  File "/<DELETED>/lib/python2.7/site-packages/nsq/reader.py", line 248, in _on_message

    self._handle_message(conn, message)

  File "/<DELETED>/lib/python2.7/site-packages/nsq/reader.py", line 286, in _handle_message

    assert success is not None, 'ambiguous return value for synchronous mode'

AssertionError: ambiguous return value for synchronous mode

ERROR:root:[monkeybrain:4150:test:test_channel1] failed to handle_message() <nsq.message.Message object at 0x110f06fd0>

So, the message is received and printed in the callback, check. But then something else happens there. I also am very new to NSQ (just started playing with today) so may not be properly handling the message in the callback, sending the correct ack or something. I'll be able to play around with it more tomorrow, but if something obvious I'm doing or not doing jumps out to you, feel free to let me know. So far I really like what I'm seeing with NSQ and will likely be incorporating it into our infrastructure. I'm glad I was able to help identify some issues, and your quick response and fix inspires confidence in the integrity and longevity of NSQ.

Thanks

- Joe

[Jehiah Czebotar]

Thanks for the confirming that the fix worked.

```
def process_message(message):
print message
return True
```

In synchronous mode for pynsq the result from the message handler
tells nsq weather or not you successfully finished the message. If you
return `True` NSQ gets an acknowledgement and considers that message
done. If the function returns False or if the process dies before
responding (say you were inserting into a database, and the database
was unavailable, or you out right killed the process) the NSQ keeps
the message around and after a delay it gives the message out again
for processing.

(side note from the logging in your examples. If you don't have a
particular logging format you setup, I suggest leveraging `import
tornado.options; tornado.options.parse_command_line()` we have been
very happy with using that to setup our python logging at bitly, and
it gives command line args like `--logging=warning` which are quite
useful)

--
Jehiah