Mongo connection times out, but only when it is used by a dependency

I assume, your configuration is not working. Please turn on logging: GitHub - zookzook/elixir-mongodb-driver: MongoDB driver for Elixir · GitHub, then you see more information about.

Thanks for the prompt reply @zookzook! This is interesting. I have verified that BOTH app1 and app2 have the IDENTICAL configuration options, something like this:

[
  name: :my_mongo,
  pool_size: 20,
  url: "mongodb://:@localhost:/app1_dev",
  timeout: 15000,
  ssl: false
]

Note that the URL looks funny in dev because we don’t specify a user, password, port, or parameters (which do get set when connecting to a production mongo instance).

What is really curious is that BOTH app1 AND app2 show errors on startup when I set the config to include log: true:

10:13:33.630 [error] an exception was raised logging %DBConnection.LogEntry{call: :execute, connection_time: 5298000, decode_time: 6000, idle_time: 548338000, params: [], pool_time: 147000, query: %Mongo.Query{action: {:exec_hello, []}}, result: {:ok, %Mongo.Query{action: {:exec_hello, []}}, {%{"code" => 59, "codeName" => "CommandNotFound", "errmsg" => "no such command: 'helloOk'", "ok" => 0.0}, %Mongo.Events.CommandStartedEvent{command: :hello, command_name: :hello, connection_id: #PID<0.815.0>, database_name: "admin", operation_id: nil, request_id: 1}, 0, 5240}}}: ** (BadFunctionError) expected a function, got: true
    (db_connection 2.4.2) lib/db_connection.ex:1532: DBConnection.log/2
    (db_connection 2.4.2) lib/db_connection.ex:1510: DBConnection.log/5
    (mongodb_driver 0.9.2) lib/mongo.ex:1526: Mongo.exec_hello/2
    (stdlib 3.16.1) timer.erl:166: :timer.tc/1
    (mongodb_driver 0.9.2) lib/mongo/monitor.ex:239: Mongo.Monitor.get_server_description/1
    (mongodb_driver 0.9.2) lib/mongo/monitor.ex:164: Mongo.Monitor.update_server_description/1
    (mongodb_driver 0.9.2) lib/mongo/monitor.ex:151: Mongo.Monitor.handle_info/2
    (stdlib 3.16.1) gen_server.erl:695: :gen_server.try_dispatch/4
    (stdlib 3.16.1) gen_server.erl:771: :gen_server.handle_msg/6
    (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

app1 throws 3 of these errors, and then they pop up intermittently, but app1 can go on to successfully issue commands, e.g.

# app1
iex> Mongo.insert_one(:my_mongo, "foo", %{what: "up"})
{:ok,
 %Mongo.InsertOneResult{
   acknowledged: true,
   inserted_id: #BSON.ObjectId<633d93aac6e47b35cb0d1fc5>
 }}

whereas app2 just throws an unending stream of these errors into the log. The same command on app2 yields a timeout:

# app2
iex> Mongo.insert_one(:my_mongo, "foo", %{what: "up"})
** (exit) exited in: GenServer.call(:my_mongo, {:checkout_session, :write, [write_counter: 1]}, 60000)
    ** (EXIT) time out
    (elixir 1.13.4) lib/gen_server.ex:1030: GenServer.call/3
    (mongodb_driver 0.9.2) lib/mongo/session.ex:142: Mongo.Session.start_session/3
    (mongodb_driver 0.9.2) lib/mongo/session.ex:694: Mongo.Session.in_session/5
    (mongodb_driver 0.9.2) lib/mongo.ex:1482: Mongo.issue_command/4
    (mongodb_driver 0.9.2) lib/mongo.ex:849: Mongo.insert_one/4

It’s like Mongo “knows” how its server is getting started or something. Very curious. Any other ideas for what could explain this behavior?

I just noticed app1 shows "mongodb_driver": {:hex, :mongodb_driver, "0.9.1" in its mix.lock whereas app2 specifies "mongodb_driver": {:hex, :mongodb_driver, "0.9.2" … so I’m gonna suss that out

If both apps have identical configurations then they started the supervisor related stuff twice. Use only one configuration. A topology should only started as a singleton.

To clarify: the supervisor is only started once, I’m just comparing behaviors between the 2 apps. When app1 is run as a stand-alone app, it starts up the supervisor and Mongo. When app2 starts, it doesn’t explicitly start anything, it defers to app1 to start up its stuff. (I only explored variants to see if I could figure out what was going on here).

Aha, the problem seems to be with version 0.9.2. As soon as I force app2 to use 0.9.1, it behaves the same way as app1: the log periodically shows the error (see above), but it is able to issue commands.

So really this has nothing to do with supervisors, it’s just something to do with differences between v0.9.1 and v0.9.2. The fact that errors are being logged may indicate something problematic, however.

I should add that I’m connecting to an instance of mongo v4.0.0 – this is because in production we rely on AWS DocumentDB, and v4.0.0 seems to be the most similar.

The driver 0.9.2 does not support 4.0. Sorry, you need to downgrade the driver. It does not support AWS DocumentDB.

Ok, we’ll pin it to v0.9.1. Thanks for the responses! They are much appreciated.
This really is a great driver – I’d love to see an Ecto adapter for it. We’ve got a handful of code that could maybe be adapted for that.

Interesting re DocumentDB: we are using DocumentDB in production with mongodb_driver v0.9.1 and it has been working fine – admittedly our queries are limited to mostly CRUD without a lot of filters or sorting, but it hasn’t had any issues.

The handshake workflow changed. Instead of using ismaster, the new handshake workflow uses hello!

The hello command was introduced with Mongo 4.2 or 4.4, so I decided to use the new hello command.

I think, you found a bug in the hello command. I will fix it and then the driver should work with AWS DocumentDB!

That’s great! Do you want me to file a bug with steps to reproduce?