Intermittent RuntimeError (Timed out waiting for 2 bytes from Neo4j (after 10 seconds)) on bolt

[klobuczek]

When running bolt protocol I am getting intermittent issues: RuntimeError (Timed out waiting for 2 bytes from Neo4j (after 10 seconds)) which are hard to pinpoint and for which it is hard to detect a pattern,

Additional information which could be helpful if relevent to your issue:

Heinrich Klobuczek @klobuczek Oct 27 14:16 I just started swicthing our application from http to bolt. It partially works but I am getting a lot of those exceptions: RuntimeError (Timed out waiting for 2 bytes from Neo4j (after 10 seconds)) anyone has an idea from the top of the head?

Brian Underwood @cheerfulstoic Oct 27 14:55 We’ve seen that some. It generally means that the ruby client thinks that there is something to get from the server but the server isn’t sending anything back (probably because the client is making a bad assumption) There’s a dance back and forth between the client and the server and in each direction a certain set of bytes is expected in a certain order. Probably the ruby client missed a step in the dance

Code example (inline, gist, or repo)

Runtime information:

Neo4j database version: neo4j gem version: neo4j-core gem version:

[RyanSnodgrass]

I'm getting the same thing. I'm on ruby 2.2.5 and neo4j.rb 8.0.9

I'm running through graphstory using neo4j database 3.1.0

[RyanSnodgrass]

After playing with the bolt protocol I am now getting favorable response times at almost the same response time as http on a local host. When it works. I still have to install a 3.x neo4j database on my local machine to test the difference using bolt. I am testing bolt protocol on the free trial Azure instance on graphstory.

However, I am still seeing it hang for a few seconds then get RuntimeError: Timed out waiting for 2 bytes from Neo4j (after 10 seconds) every 3 out of 4 queries or so.

The stack trace is this:

puts Benchmark.measure { puts Report.first.name }
WARNING: The index option is no longer supported (Defined on Term for name)
WARNING: The index option is no longer supported (Defined on Report for name)
 CYPHER
  MATCH (n:`Report`:`SerializableNode`)
  RETURN n
  ORDER BY n.uuid
  LIMIT {limit_1} | {:limit_1=>1}
RuntimeError: Timed out waiting for 2 bytes from Neo4j (after 10 seconds)
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:195:in `rescue in recvmsg'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:189:in `recvmsg'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:221:in `flush_response'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:199:in `flush_messages'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:62:in `call'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:62:in `block in extract_message_groups'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:61:in `loop'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:61:in `extract_message_groups'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:15:in `block in initialize'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:14:in `map'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:14:in `initialize'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:97:in `new'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:97:in `block in build_response'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:96:in `catch'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:96:in `build_response'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:53:in `query_set'
... 3 levels...
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:116:in `queries'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:108:in `query'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session.rb:36:in `block (2 levels) in <class:CypherSession>'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j-core/query.rb:240:in `response'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j-core/query.rb:311:in `pluck'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-8.0.9/lib/neo4j/active_node/query_methods.rb:16:in `first'
    from (irb):28:in `block in irb_binding'
    from /usr/local/rvm/rubies/ruby-2.2.5/lib/ruby/2.2.0/benchmark.rb:288:in `measure'
    from (irb):28
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/console.rb:110:in `start'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/console.rb:9:in `start'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:68:in `console'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
    from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands.rb:17:in `<top (required)>'
    from bin/rails:4:in `require'
    from bin/rails:4:in `<main>'

When it works i get response times of about 110 milliseconds.

2.2.5 :004 > puts Benchmark.measure { puts Report.first.name }
WARNING: The index option is no longer supported (Defined on Report for name)
 CYPHER
  MATCH (n:`Report`:`SerializableNode`)
  RETURN n
  ORDER BY n.uuid
  LIMIT {limit_1} | {:limit_1=>1}
Employee Counts
  0.010000   0.000000   0.010000 (  0.116625)
 => nil

When it hangs constantly, I'll ctrl-c to cancel and retry over and over, then sometimes I'll get an undefined type method for nil class error. Maybe this will help diagnose the issue.

2.2.5 :038 > puts Benchmark.measure { puts Report.first.name }
WARNING: The index option is no longer supported (Defined on Term for name)
WARNING: The index option is no longer supported (Defined on Report for name)
 CYPHER
  MATCH (n:`Report`:`SerializableNode`)
  RETURN n
  ORDER BY n.uuid
  LIMIT {limit_1} | {:limit_1=>1}
NoMethodError: undefined method `type' for nil:NilClass
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:127:in `validate_message_type!'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:56:in `extract_message_groups'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:15:in `block in initialize'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:14:in `map'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/responses/bolt.rb:14:in `initialize'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:97:in `new'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:97:in `block in build_response'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:96:in `catch'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:96:in `build_response'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors/bolt.rb:53:in `query_set'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:117:in `block in queries'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:199:in `new_or_current_transaction'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:116:in `queries'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session/adaptors.rb:108:in `query'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j/core/cypher_session.rb:36:in `block (2 levels) in <class:CypherSession>'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j-core/query.rb:240:in `response'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-core-7.0.5/lib/neo4j-core/query.rb:311:in `pluck'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/neo4j-8.0.9/lib/neo4j/active_node/query_methods.rb:16:in `first'
	from (irb):38:in `block in irb_binding'
	from /usr/local/rvm/rubies/ruby-2.2.5/lib/ruby/2.2.0/benchmark.rb:288:in `measure'
	from (irb):38
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/console.rb:110:in `start'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/console.rb:9:in `start'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:68:in `console'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
	from /usr/local/rvm/gems/ruby-2.2.5@Fenrir/gems/railties-4.2.7.1/lib/rails/commands.rb:17:in `<top (required)>'
	from bin/rails:4:in `require'
	from bin/rails:4:in `<main>'

[tjad]

I am also seeing this intermittent error using bolt protocol, though I am only getting it on the first request - frequent subsequent request work nicely.

I haven't left prolonged periods yet.

Client - Ubuntu 17.04 Desktop activemodel (5.1.1) neo4j (8.0.17) activemodel (>= 4.0) activesupport (>= 4.0) neo4j-core (>= 7.0.0) orm_adapter (~> 0.5.0) neo4j-core (7.1.2) activesupport (>= 4.0) faraday (>= 0.9.0) faraday_middleware (~> 0.10.0) faraday_middleware-multi_json httpclient json multi_json neo4j-rake_tasks (>= 0.3.0) typhoeus (>= 1.1.2)

Server - Ubuntu 17.04 Server neo4j 3.2.0 instance

Note that my server is a vagrant(virtualbox) vm

[himberjack]

Joining. We are getting

'RuntimeError: Timed out waiting for 2 bytes from Neo4j'

Every 2nd query. If we cancel the frozen query and re-run - it will work. Has to do something with the bold protocol

[cheerfulstoic]

;( Sorry, I didn't realize I hadn't commented on this.

There is definitely an issue with the Bolt protocol, unfortunately. It almost entirely works, but I'd suggest using HTTP for the time being

[kfreytag]

@cheerfulstoic is the issue with the implementation of the Bolt protocol within neo4jrb or do you believe that there is a fundamental issue with the Bolt protocol? If the latter, please do let me know.

[cheerfulstoic]

I would be really surprised if it was an issue with the Bolt protocol. Neo4j, Inc has that working successfully in a number of different languages. I think there's just some rare condition that hasn't yet been fixed in the Ruby implementation (and I haven't had time to dig into). I would review the heck out of any PR that might fix it ;)

[shobee]

Any new insights on this topic? We are running into this error randomly. But one of our tests if failing relatively often when using create_list from Factory Bot.

[cheerfulstoic]

@shobee I did some refactoring on the master branch of the neo4j-core gem. You might try that to see if it works better for you (it also has some improvements that definitely speed up the Bolt adaptor). You can load the master branch in you Gemfile like:

gem 'neo4j-core', github: 'neo4jrb/neo4j-core', branch: 'master`

Somebody using the master branch did still report having errors, but I think there's a chance it might help a bit.

Unfortunately I haven't had time to look into it further.