migrations timing out with simple drop_constraint / fixes with disabled_transactions!?

[leviwilson]

We have ran into seemingly random issues particularly with regard to either adding or removing constraints. A recent example of this is a simple migration that is defined like so:

class RemoveDocumentTypeConstraints < Neo4j::Migrations::Base
  def up
    drop_constraint :DocumentType, :uuid
    drop_constraint :DocumentType, :external_id
  end

  def down
    add_constraint :DocumentType, :uuid
    add_constraint :DocumentType, :external_id
  end
end

In a project of ours we have, adding this migration causes the DROP CONSTRAINT to timeout when all of the migrations run against an empty graph (to start out with).

Why? I'm unsure. But if I add a disable_transactions! in that definition everything is hunky dory.

Here is a sample stack trace that happens without having disable_transactions! in there:

== 20171128152132 RemoveDocumentTypeConstraints: running... ====================
 CYPHER DROP CONSTRAINT ON (n:`DocumentType`) ASSERT n.`uuid` IS UNIQUE
rake aborted!
Faraday::TimeoutError: request timed out
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/adapters/faraday.rb:100:in `block in request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/callbacks.rb:128:in `block in execute_callbacks'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/callbacks.rb:127:in `each'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/callbacks.rb:127:in `execute_callbacks'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/operations.rb:35:in `finish'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/easy_factory.rb:159:in `block in set_callback'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/ethon-0.10.1/lib/ethon/easy/response_callbacks.rb:68:in `block in complete'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/ethon-0.10.1/lib/ethon/easy/response_callbacks.rb:68:in `each'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/ethon-0.10.1/lib/ethon/easy/response_callbacks.rb:68:in `complete'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/ethon-0.10.1/lib/ethon/easy/operations.rb:33:in `perform'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/operations.rb:16:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/cacheable.rb:18:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/block_connection.rb:31:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/stubbable.rb:25:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/request/before.rb:26:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/adapters/faraday.rb:82:in `perform_request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/typhoeus-1.3.0/lib/typhoeus/adapters/faraday.rb:72:in `call'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/faraday_middleware-0.10.1/lib/faraday_middleware/response_middleware.rb:30:in `call'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/faraday_middleware-0.10.1/lib/faraday_middleware/request/encode_json.rb:23:in `call'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/faraday-0.13.1/lib/faraday/rack_builder.rb:141:in `build_response'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/faraday-0.13.1/lib/faraday/connection.rb:387:in `run_request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:129:in `block (2 levels) in request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:187:in `wrap_connection_failed!'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:128:in `block in request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/instrumentable.rb:29:in `block (3 levels) in instrument'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.6/lib/active_support/notifications.rb:164:in `block in instrument'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.6/lib/active_support/notifications.rb:164:in `instrument'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/instrumentable.rb:29:in `block (2 levels) in instrument'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:127:in `call'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:127:in `request'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:141:in `get'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session/adaptors/http.rb:62:in `constraints'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/cypher_session.rb:36:in `block (2 levels) in <class:CypherSession>'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/label.rb:100:in `constraints'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/core/label.rb:124:in `constraint?'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/helpers/schema.rb:27:in `drop_constraint'
/Users/lwilson/git/super_project/db/neo4j/migrate/20171128152132_remove_document_type_constraints.rb:6:in `up'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:56:in `public_send'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:56:in `block (2 levels) in run_migration'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:71:in `log_queries'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:56:in `block in run_migration'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/active_base.rb:40:in `block in run_transaction'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-core-7.0.9/lib/neo4j/transaction.rb:135:in `run'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/active_base.rb:39:in `run_transaction'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:66:in `migration_transaction'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:56:in `run_migration'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:33:in `migrate_up'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:16:in `block in migrate'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/base.rb:15:in `migrate'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:127:in `block in migrate'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:133:in `migration_message'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:125:in `migrate'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:26:in `block in all'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:24:in `each'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/migrations/runner.rb:24:in `all'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/tasks/migration.rake:116:in `block (3 levels) in <top (required)>'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/neo4j-8.1.5/lib/neo4j/tasks/migration.rake:45:in `block (2 levels) in <top (required)>'
/Users/lwilson/.rvm/gems/ruby-2.3.1/gems/rake-12.1.0/exe/rake:27:in `<top (required)>'
/Users/lwilson/.rvm/gems/ruby-2.3.1/bin/ruby_executable_hooks:15:in `eval'
/Users/lwilson/.rvm/gems/ruby-2.3.1/bin/ruby_executable_hooks:15:in `<main>'
Tasks: TOP => neo4j:migrate:all
(See full trace by running task with --trace)

Only thing I could maybe think of that might contribute to the issue is the fact that in an earlier migration that constraint would've been initially added?

Just curious if anyone else has ran into this issue or could provide insight as to when we should or should not be using disable_transactions! as the documentation only seems to suggest that you should only need to use that if you're mixing schema changes with node creation, etc.

Runtime information:

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

[jorroll]

@leviwilson I'm guessing this is a limitation of Neo4j. Can you try checking the database logs to see if it contains more information about the failure? Faraday::TimeoutError: request timed out isn't very specific.

[leviwilson]

@thefliik oh, surely! Understood that's not the root cause; my 🤔 is that for whatever reasons, within a transaction the request is taking longer than the default 60s, whereas with disable_transactions! the request takes place immediately.

I can look at the logs, but I was more curious what was happening under the scenes to cause it to go well beyond what it takes in the absence of a transaction.

[subvertallchris]

It's been a while but I remember this being a Neo4j limitation. Certain schema modifications within transactions would always time out.

[jorroll]

Before you created this issue, I was under the impression that Neo4j only allowed one schema modification per transaction. The fact that you were able to add two constraints as part of the original migration calls my belief into question though. I was thinking that, perhaps, the Neo4j logs might contain some error info / explanation that never made it to Faraday.

[leviwilson]

@thefliik ahh, I gotcha. I hadn't even considered that to be honest. I'll see if that yields any details 👍