UndefinedFunctionError during Bolt.Sips.start_link after migrating from 1.3.0 to 1.4.0 or 1.5.1

Tomboyo commented 4 years ago

Environment

Elixir 1.8.2 (compiled with Erlang/OTP 20), Interactive Elixir (1.8.2)
Neo4J 3.5.6
Connecting via bolt:// (see below)
Bolt.Sips 1.5.1
Ubuntu 18.04.2 LTS (Bionic Beaver)

Current behavior

I call the following code in IEX to start my bolt.sips connection, unchanged from how I did with version 1.3.0 of Bolt Sips:

Bolt.Sips.start_link([       
  url: "bolt://localhost:7687",
  ssl: true,
  basic_auth: [username: "neo4j", password: "secret"]
])

and the following is logged in response:

18:29:55.186 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"

18:29:55.186 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"

18:29:55.187 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>

18:29:55.187 [debug] S: HANDSHAKE ~ 3

18:29:55.187 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]

18:29:55.187 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>

18:29:55.187 [debug] S: HANDSHAKE ~ 3

18:29:55.187 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]

18:29:55.187 [error] GenServer #PID<0.574.0> terminating
** (RuntimeError) connect raised UndefinedFunctionError exception. The exception details are hidden, as they may contain sensitive data such as database credentials. You may set :show_sensitive_data_on_connection_error to true when starting your connection if you wish to see all of the details
    (bolt_sips) Bolt.Sips.Internals.PackStream.Encoder.encode/2
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:145: Bolt.Sips.Internals.PackStream.Message.Encoder.encode_message/4
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:105: Bolt.Sips.Internals.PackStream.Message.Encoder.call_encode/3
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_helper.ex:20: Bolt.Sips.Internals.BoltProtocolHelper.send_message/4 
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_v3.ex:28: Bolt.Sips.Internals.BoltProtocolV3.hello/5
    (bolt_sips) lib/bolt_sips/protocol.ex:39: Bolt.Sips.Protocol.connect/1
    (db_connection) lib/db_connection/connection.ex:69: DBConnection.Connection.connect/2
    (connection) lib/connection.ex:622: Connection.enter_connect/5
Last message: nil
State: Bolt.Sips.Protocol

Several such errors are logged for various PIDs.

[EDIT] If I downgrade to 1.4.0 I receive a similar repeated error:

23:48:54.658 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [2, 1, 0, 0]"

23:48:54.659 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x2>>

23:48:54.659 [debug] S: HANDSHAKE ~ 2

23:48:54.659 [debug] C: INIT ~ ["BoltSips/", %{credentials: "secret", principal: "neo4j", scheme: "basic"}]

23:48:54.660 [error] GenServer #PID<0.338.0> terminating
** (RuntimeError) connect raised UndefinedFunctionError exception. The exception details are hidden, as they may contain sensitive data such as database credentials. You may set :show_sensitive_data_on_connection_error to true when starting your connection if you wish to see all of the details
    (bolt_sips) Bolt.Sips.Internals.PackStream.Encoder.encode/2
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:209: Bolt.Sips.Internals.PackStream.Message.Encoder.do_encode/3
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol.ex:177: Bolt.Sips.Internals.BoltProtocol.send_message/4
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol.ex:155: Bolt.Sips.Internals.BoltProtocol.init/5
    (bolt_sips) lib/bolt_sips/protocol.ex:39: Bolt.Sips.Protocol.connect/1
    (db_connection) lib/db_connection/connection.ex:69: DBConnection.Connection.connect/2
    (connection) lib/connection.ex:622: Connection.enter_connect/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: nil
State: Bolt.Sips.Protocol

Downgrading further to 1.3.0 resolves the issue as expected, so this appears to be an issue for me only since 1.4.0.

Expected behavior

I expected this to establish a database connection with Neo4j, as it did in version 1.3.0.

I tried passing the :show_sensitive_... flag along to Bolt.Sips.start_link, not knowing if it would ultimately be passed down to DBConnection, but the same message was logged without additional information.

yatender-oktalk commented 4 years ago

Bolt.Sips.start_link(url: "bolt://secret@localhost") try this, mine is working fine & getting connected.

florinpatrascu commented 4 years ago

@Tomboyo - can you please try this:

Bolt.Sips.start_link([       
  url: "bolt://localhost:7687",
  ssl: true,
  basic_auth: [username: "neo4j", password: "secret"],
  socket: Bolt.Sips.Socket
])

BTW, your original config will work with Bolt.Sips 2.x. ; we reworked the config support, among other features.

And also, unrelated to Bolt.Sips but would help your app, see if you can upgrade the Erlang version?! - see the discussion above: ecto/db_connection/issues/127, for brevity.

Tomboyo commented 4 years ago

I checked for software updates, but there weren't available via aptitude. For clarity, I'm on Erlang/OTP 22; my un-redacted version output is:

Erlang/OTP 22 [erts-10.4] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]
Elixir 1.8.2 (compiled with Erlang/OTP 20)

I have another OS with locally-compiled Elixir that I can use to test against bleeding-edge elixir/erlang, if that would be helpful. I think it's on 1.9.something right now.

Following @florinpatrascu 's suggestion to add the socket option garnered similar errors. In 1.5.1 I get:

14:41:06.834 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"

14:41:06.835 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>

14:41:06.835 [debug] S: HANDSHAKE ~ 3

14:41:06.835 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]

14:41:06.836 [error] GenServer #PID<0.334.0> terminating
** (RuntimeError) connect raised UndefinedFunctionError exception. The exception details are hidden, as they may contain sensitive data such as database credentials. You may set :show_sensitive_data_on_connection_error to true when starting your connection if you wish to see all of the details
    (bolt_sips) Bolt.Sips.Internals.PackStream.Encoder.encode/2
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:145: Bolt.Sips.Internals.PackStream.Message.Encoder.encode_message/4
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:105: Bolt.Sips.Internals.PackStream.Message.Encoder.call_encode/3
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_helper.ex:20: Bolt.Sips.Internals.BoltProtocolHelper.send_message/4
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_v3.ex:28: Bolt.Sips.Internals.BoltProtocolV3.hello/5
    (bolt_sips) lib/bolt_sips/protocol.ex:39: Bolt.Sips.Protocol.connect/1 
    (db_connection) lib/db_connection/connection.ex:69: DBConnection.Connection.connect/2
    (connection) lib/connection.ex:622: Connection.enter_connect/5
Last message: nil
State: Bolt.Sips.Protocol

In 1.4.0 I get:

14:39:07.090 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [2, 1, 0, 0]"

14:39:07.091 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x2>>

14:39:07.091 [debug] S: HANDSHAKE ~ 2

14:39:07.091 [debug] C: INIT ~ ["BoltSips/", %{credentials: "secret", principal: "neo4j", scheme: "basic"}]

14:39:07.092 [error] GenServer #PID<0.588.0> terminating
** (RuntimeError) connect raised UndefinedFunctionError exception. The exception details are hidden, as they may contain sensitive data such as database credentials. You may set :show_sensitive_data_on_connection_error to true when starting your connection if you wish to see all of the details
    (bolt_sips) Bolt.Sips.Internals.PackStream.Encoder.encode/2
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:209: Bolt.Sips.Internals.PackStream.Message.Encoder.do_encode/3
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol.ex:177: Bolt.Sips.Internals.BoltProtocol.send_message/4
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol.ex:155: Bolt.Sips.Internals.BoltProtocol.init/5
    (bolt_sips) lib/bolt_sips/protocol.ex:39: Bolt.Sips.Protocol.connect/1
    (db_connection) lib/db_connection/connection.ex:69: DBConnection.Connection.connect/2
    (connection) lib/connection.ex:622: Connection.enter_connect/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: nil
State: Bolt.Sips.Protocol

Following @yatender-oktalk 's suggestion met with more of the same in 1.5.1:

14:43:52.207 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"

14:43:52.208 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>

14:43:52.208 [debug] S: HANDSHAKE ~ 3

14:43:52.208 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]

14:43:52.209 [error] GenServer #PID<0.372.0> terminating
** (RuntimeError) connect raised UndefinedFunctionError exception. The exception details are hidden, as they may contain sensitive data such as database credentials. You may set :show_sensitive_data_on_connection_error to true when starting your connection if you wish to see all of the details
    (bolt_sips) Bolt.Sips.Internals.PackStream.Encoder.encode/2
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:145: Bolt.Sips.Internals.PackStream.Message.Encoder.encode_message/4
    (bolt_sips) lib/bolt_sips/internals/pack_stream/message/encoder.ex:105: Bolt.Sips.Internals.PackStream.Message.Encoder.call_encode/3
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_helper.ex:20: Bolt.Sips.Internals.BoltProtocolHelper.send_message/4
    (bolt_sips) lib/bolt_sips/internals/bolt_protocol_v3.ex:28: Bolt.Sips.Internals.BoltProtocolV3.hello/5
    (bolt_sips) lib/bolt_sips/protocol.ex:39: Bolt.Sips.Protocol.connect/1 
    (db_connection) lib/db_connection/connection.ex:69: DBConnection.Connection.connect/2
    (connection) lib/connection.ex:622: Connection.enter_connect/5
Last message: nil
State: Bolt.Sips.Protocol

I appreciate the help! Happy to try any other suggestions as well.

florinpatrascu commented 4 years ago

I've tried using your server version, and I can connect. Basically, in the root of the bolt_sips project (v1.5.1), I am running the following:

$ DEBUG=1 iex -S mix

Erlang/OTP 21 [erts-10.2.3] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe]

Interactive Elixir (1.8.1) - press Ctrl+C to exit (type h() ENTER for help)
iex» {ok, neo}= Bolt.Sips.start_link([
...»   ssl: true,
...»   basic_auth: [username: "neo4j", password: "secret"],
...»   url: "bolt://localhost:7472"
...» ])
{:ok, #PID<0.244.0>}
iex» 2019-08-11 15:33:46.017 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"
2019-08-11 15:33:46.017 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"
2019-08-11 15:33:46.017 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"
2019-08-11 15:33:46.017 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"
2019-08-11 15:33:46.017 [debug] C: HANDSHAKE ~ "<<0x60, 0x60, 0xB0, 0x17>> [3, 2, 1, 0]"
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ 3
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ 3
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ 3
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ <<0x0, 0x0, 0x0, 0x3>>
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ 3
2019-08-11 15:33:46.023 [debug] S: HANDSHAKE ~ 3
2019-08-11 15:33:46.032 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]
2019-08-11 15:33:46.032 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]
2019-08-11 15:33:46.032 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]
2019-08-11 15:33:46.032 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]
2019-08-11 15:33:46.032 [debug] C: HELLO ~ [%{credentials: "secret", principal: "neo4j", scheme: "basic", user_agent: "BoltSips/1.5.1"}]
2019-08-11 15:33:46.089 [debug] C: HELLO ~ <<0x0, 0x4D, 0xB1, 0x1, 0xA4, 0x8B, 0x63, 0x72, 0x65, 0x64, 0x65, 0x6E, 0x74, 0x69, 0x61, 0x6C, 0x73, 0x86, 0x73, 0x65, 0x63, 0x72, 0x65, 0x74, 0x89, 0x70, 0x72, 0x69, 0x6E, 0x63, 0x69, 0x70, 0x61, 0x6C, 0x85, 0x6E, 0x65, 0x6F, 0x34, 0x6A, 0x86, 0x73, 0x63, 0x68, 0x65, 0x6D, 0x65, 0x85, 0x62, 0x61, 0x73, 0x69, 0x63, 0x8A, 0x75, 0x73, 0x65, 0x72, 0x5F, 0x61, 0x67, 0x65, 0x6E, 0x74, 0x8E, 0x42, 0x6F, 0x6C, 0x74, 0x53, 0x69, 0x70, 0x73, 0x2F, 0x31, 0x2E, 0x35, 0x2E, 0x31, 0x0, 0x0>>
2019-08-11 15:33:46.091 [debug] C: HELLO ~ <<0x0, 0x4D, 0xB1, 0x1, 0xA4, 0x8B, 0x63, 0x72, 0x65, 0x64, 0x65, 0x6E, 0x7 ...

and then trying simple queries also works, excerpt:

iex» Bolt.Sips.query!(Bolt.Sips.conn, "RETURN 1 as n")

2019-08-11 15:36:30.720 [debug] C: RUN ~ ["RETURN 1 as n", %{}, %{}]
2019-08-11 15:36:30.723 [debug] C: RUN ~ <<0x0, 0x12, 0xB3, 0x10, 0x8D, 0x52, 0x45, 0x54, 0x55, 0x52, 0x4E, 0x20, 0x31, 0x20, 0x61, 0x73, 0x20, 0x6E, 0xA0, 0xA0, 0x0, 0x0>>
2019-08-11 15:36:30.735 [debug] S: SUCCESS ~ <<0xA2, 0x87, 0x74, 0x5F, 0x66, 0x69, 0x72, 0x73, 0x74, 0xA, 0x86, 0x66, 0x69, 0x65, 0x6C, 0x64, 0x73, 0x91, 0x81, 0x6E>>
2019-08-11 15:36:30.740 [debug] S: SUCCESS ~ %{"fields" => ["n"], "t_first" => 10}
2019-08-11 15:36:30.742 [debug] C: PULL_ALL ~ []
2019-08-11 15:36:30.743 [debug] C: PULL_ALL ~ <<0x0, 0x2, 0xB0, 0x3F, 0x0, 0x0>>
2019-08-11 15:36:30.744 [debug] S: RECORD ~ <<0x91, 0x1>>
2019-08-11 15:36:30.747 [debug] S: RECORD ~ [1]
2019-08-11 15:36:30.747 [debug] S: SUCCESS ~ <<0xA3, 0x88, 0x62, 0x6F, 0x6F, 0x6B, 0x6D, 0x61, 0x72, 0x6B, 0xD0, 0x15, 0x6E, 0x65, 0x6F, 0x34, 0x6A, 0x3A, 0x62, 0x6F, 0x6F, 0x6B, 0x6D, 0x61, 0x72, 0x6B, 0x3A, 0x76, 0x31, 0x3A, 0x74, 0x78, 0x31, 0x84, 0x74, 0x79, 0x70, 0x65, 0x81, 0x72, 0x86, 0x74, 0x5F, 0x6C, 0x61, 0x73, 0x74, 0x0>>
2019-08-11 15:36:30.752 [debug] S: SUCCESS ~ %{"bookmark" => "neo4j:bookmark:v1:tx1", "t_last" => 0, "type" => "r"}
[%{"n" => 1}]

observe please the port: 7472. This is the default bolt port for, a fresh install, according to the neo4j.conf file, excerpt:

# Bolt connector
dbms.connector.bolt.enabled=true
#dbms.connector.bolt.tls_level=OPTIONAL
dbms.connector.bolt.listen_address=localhost:7472

florinpatrascu commented 4 years ago

I’ll close this for now, as I’m not able to reproduce it and there’s no new reports on it. Please feel free to reopen this issue should you encounter related troubles or find additional details that can help us all understand better your case.

Tomboyo commented 4 years ago

Fair enough! I'll try to narrow down what's going wrong at some point and circle back here if I can deduce where the error is. It sounds like it's an environmental problem given you were able to connect to my build of neo.

Thanks all for your time and help!

On Thu, Aug 15, 2019, 1:57 PM Florin notifications@github.com wrote:

Closed #72 https://github.com/florinpatrascu/bolt_sips/issues/72.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/florinpatrascu/bolt_sips/issues/72?email_source=notifications&email_token=AA2OQ6MP5GOU4N3N2QYLJOLQEWKIJA5CNFSM4IK23U32YY3PNVWWK3TUL52HS4DFWZEXG43VMVCXMZLOORHG65DJMZUWGYLUNFXW5KTDN5WW2ZLOORPWSZGOTCNA4BY#event-2560232967, or mute the thread https://github.com/notifications/unsubscribe-auth/AA2OQ6NOXUCPBDATVYJUVT3QEWKIJANCNFSM4IK23U3Q .

florinpatrascu commented 4 years ago

Please do reopen it, if you can help us reproduce that error. We definitely don’t like losing sight of a potential trouble. Thanks again for trying our implementation and please try to stay as close as possible to the most recent releases :) /cc @dominique-vassard

Tomboyo commented 4 years ago

I've confirmed this was a problem on my end, thought I'd share. I'm not precisely sure what happened because I had an unconventional, wrong, misguided bit of project structuring, but I believe that structuring broke dependency lookup for :ssl and :crypto. I initially had to add :ssl to my extra_applications, which resolved the issue. I've since fixed the structure, removed the dependency on :ssl, and dependency resolution works again. Everything is fine on 1.5.1. Bolt Sips continues to be excellent. :D Thanks again.

florinpatrascu commented 4 years ago

Many thanks, for the feedback. It really helps us maintaining this project. Thanks you!

florinpatrascu / bolt_sips