:gen_event handler

[treble37]

Hello, so on a staging environment box, I'm getting the below in an iex console for a Phoenix application....The error message is rather cryptic, so it's unclear what is wrong. Any tips in the right direction?

iex server-xxx 2> Logger.info("Hello world")
:ok
iex server-xxx 3> :gen_event handler Timber.LoggerBackends.HTTP installed in Logger terminating
** (exit) an exception was raised:
    ** (ArgumentError) argument error
        (stdlib) :ets.lookup_element(:hackney_config, :mod_metrics, 2)
        (hackney) /root/project/deps/hackney/src/hackney_metrics.erl:27: :hackney_metrics.get_engine/0
        (hackney) /root/project/deps/hackney/src/hackney_connect.erl:78: :hackney_connect.create_connection/5
        (hackney) /root/project/deps/hackney/src/hackney_connect.erl:47: :hackney_connect.connect/5
        (hackney) /root/project/deps/hackney/src/hackney.erl:330: :hackney.request/5
        (timber) lib/timber/logger_backends/http.ex:396: Timber.LoggerBackends.HTTP.transmit_buffer/2
        (timber) lib/timber/logger_backends/http.ex:211: Timber.LoggerBackends.HTTP.handle_info/2
        (stdlib) gen_event.erl:577: :gen_event.server_update/4

nil

I followed the docs:

https://docs.timber.io/setup/languages/elixir

which say:

Basic Logging
Timber works with your existing Logger calls, no changes necessary:
Logger.info("Hello world")

We are getting at least some debug logs in staging for timber.io, so it seems the setup and configuration of Timber is line with what needs to be done via the docs.

Here is the timber deps in our mix.exs file for one part of our umbrella app:

      {:timber, "~> 3.1.1"},
      {:timber_plug, "~> 1.0"},
      {:timber_phoenix, "~> 1.0"},
      {:timber_ecto, "~> 2.1.0"},
      {:timber_exceptions, "~> 2.1.0"},

And the timber deps in mix.exs for another app in our umbrella app:

      {:timber, "~> 3.1.1"},
      {:timber_ecto, "~> 2.1.0"},

If I setup my local machine with the same credentials as the staging box and to use the Timber HTTP backend, I don't get the above issue.

[treble37]

I tracked it down to a request to :hackney in Timber.HTTPClients.Hackney.

:hackney.request(method, url, req_headers, body, req_opts)

[binarylogic]

Thanks for filing this. Oh how I dislike hackney, we've wasted so much time debugging it. @mitchellhenke will take a crack at this.

[treble37]

Thank you @binarylogic and @mitchellhenke - if it helps I also ensured hackney was started in the iex console - I did an Application.started_applications/1 in the iex console on the remote environment and it showed hackney in the list of started apps.

[mitchellhenke]

@treble37 and you still see the error?

[treble37]

Yes, @mitchellhenke unfortunately....(I didn't have to start hackney as it was already started in case I didn't convey that clearly)...if you'd like I can paste the list of args passed to the hackney request - I started doing a remote debug trace but couldn't get farther than that...

[mitchellhenke]

@treble37 that'd be great 🙂

[treble37]

@mitchellhenke - here you go (with a "sanitized" auth token):

< _req_headers@1 = [{<<"Authorization">>,
                     <<"Basic MXXXXAUTH">>},
                    {<<"Content-Type">>,<<"application/msgpack">>},
                    {<<"User-Agent">>,<<"timber-elixir/">>}]
< _req_opts@1 = [{connect_timeout,5000},{recv_timeout,10000},{async,true}]
< _method@1 = post
< _headers@1 = #{<<"Authorization">> =>
                     <<"Basic MXXXXAUTH">>,
                 <<"Content-Type">> => <<"application/msgpack">>,
                 <<"User-Agent">> => <<"timber-elixir/">>}
< _url@1 = <<"https://logs.timber.io/frames">>
< _method@1 = post
< _headers@1 = #{<<"Authorization">> =>
                     <<"Basic MXXXXAUTH">>,
                 <<"Content-Type">> => <<"application/msgpack">>,
                 <<"User-Agent">> => <<"timber-elixir/">>}
< _body@1 = [145,
             [133,
              [[167|<<"context">>],
               130,
               [[167|<<"runtime">>],
                134,
                [[171|<<"application">>],192],
                [[164|<<"file">>],163|<<"iex">>],
                [[168|<<"function">>],192],
                [[164|<<"line">>],23],
                [[171|<<"module_name">>],192],
                [[166|<<"vm_pid">>],169|<<"<0.346.0>">>]],
               [[166|<<"system">>],
                130,
                [[168|<<"hostname">>],192],
                [[163|<<"pid">>]|<<"꼐">>]]],
              [[162|<<"dt">>],187|<<"2019-05-07T15:52:04.393107Z">>],
              [[165|<<"event">>],192],
              [[165|<<"level">>],164|<<"info">>],
              [[167|<<"message">>],166|<<"help 7">>]]]
< _req_headers@1 = [{<<"Authorization">>,
                     <<"Basic MXXXXAUTH">>},
                    {<<"Content-Type">>,<<"application/msgpack">>},
                    {<<"User-Agent">>,<<"timber-elixir/">>}]
< _body@1 = [145,
             [133,
              [[167|<<"context">>],
               130,
               [[167|<<"runtime">>],
                134,
                [[171|<<"application">>],192],
                [[164|<<"file">>],163|<<"iex">>],
                [[168|<<"function">>],192],
                [[164|<<"line">>],23],
                [[171|<<"module_name">>],192],
                [[166|<<"vm_pid">>],169|<<"<0.346.0>">>]],
               [[166|<<"system">>],
                130,
                [[168|<<"hostname">>],192],
                [[163|<<"pid">>]|<<"꼐">>]]],
              [[162|<<"dt">>],187|<<"2019-05-07T15:52:04.393107Z">>],
              [[165|<<"event">>],192],
              [[165|<<"level">>],164|<<"info">>],
              [[167|<<"message">>],166|<<"help 7">>]]]
< _req_headers@1 = [{<<"Authorization">>,
                     <<"Basic MXXXXAUTH">>},
                    {<<"Content-Type">>,<<"application/msgpack">>},
                    {<<"User-Agent">>,<<"timber-elixir/">>}]
< _req_opts@1 = [{connect_timeout,5000},{recv_timeout,10000},{async,true}]
< _req_opts@1 = [{connect_timeout,5000},{recv_timeout,10000},{async,true}]

[treble37]

I also haven't updated to the latest timber_ecto (running 2.1.0 rather than 2.1.1) if you think that might make a difference...

[mitchellhenke]

huh, that's odd. My suspicion was that the :hackney application wasn't started, but if it is started and still gives that error, I'm not sure. I wouldn't think timber_ecto changes would affect it.

Does the failure happen in any of the umbrella apps if you try it, or just the one?

Also what version of hackney are you on?

[treble37]

So with our remote setup, I start the iex shell in the top level of the umbrella application, which I thought means I'm interacting with all of the applications normally?

Here's the timber stuff from the mix.lock:

   "timber": {:hex, :timber, "3.1.1", "8e7916f16a90d3c773054aba7783dffb2153ed4144df6bf257869a59ec8b2d1a", [:mix], [{:hackney, "~> 1.9", [hex: :hackney, repo: "hexpm", optional: false]}, {:jason, "~> 1.1", [hex: :jason, repo: "hexpm", optional: false]}, {:msgpax, "~> 2.2", [hex: :msgpax, repo: "hexpm", optional: false]}], "hexpm"},
  "timber_ecto": {:hex, :timber_ecto, "2.1.0", "bf73d3ebc090c782973501a51224d64ddb763cac65e73ef414e2124a31dc85fc", [:mix], [{:ecto, "~> 3.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:timber, "~> 3.1", [hex: :timber, repo: "hexpm", optional: false]}], "hexpm"},
  "timber_exceptions": {:hex, :timber_exceptions, "2.1.0", "0048afd74074b1ef7f1ee88d3baf711f16700bf80a79ad13584d0a6beb5cc031", [:mix], [{:timber, "~> 3.1", [hex: :timber, repo: "hexpm", optional: false]}], "hexpm"},
  "timber_phoenix": {:hex, :timber_phoenix, "1.1.0", "cde5ee866288dc1b0f1cf8e7c1fe7657d446ddbc650361b2dc4f1fd50eda68fc", [:mix], [{:phoenix, "~> 1.2", [hex: :phoenix, repo: "hexpm", optional: false]}, {:plug, "~> 1.1", [hex: :plug, repo: "hexpm", optional: false]}, {:timber, "~> 3.1", [hex: :timber, repo: "hexpm", optional: false]}], "hexpm"},
  "timber_plug": {:hex, :timber_plug, "1.1.0", "d4c950b943775006e61ca0b6176ef7c056462df281cf48145282989e680018cc", [:mix], [{:plug, "~> 1.2", [hex: :plug, repo: "hexpm", optional: false]}, {:timber, "~> 3.1", [hex: :timber, repo: "hexpm", optional: false]}], "hexpm"},

Hackney is 1.9 apparently...there are also other versions of hackney specified for different deps like tzdata - can paste those too if needed.

[mitchellhenke]

Do you have timber installed in the root umbrella application?

[treble37]

So timber 3.1.1 is listed as a dependency in each of our 2 umbrella applications that use it in their respective mix.exs files. The top level mix.exs file does not have timber listed as a dependency if that's what you mean.

[mitchellhenke]

I created a minimal app here to try to reproduce as you've described, but I wasn't able to get the same behavior. The :hackney application not being started is still my hunch, somehow related to the umbrella application potentially.

Do your applications use the :extra_applications config in mix.exs or :applications?

[treble37]

For the umbrella that holds our repositories, in mix.exs we have:

  def application do
    [
      extra_applications: [:logger, :mnesia, :ecto_sql],
      start_phases: [init: []],
      mod: {My.Application, []}
    ]
  end

The other mix.exs for our web endpoints:

  def application do
    [
      extra_applications: [:logger, :runtime_tools],
      mod: {Web.Application, []}
    ]
  end

Thanks for making that test app....