timber-elixir
timber-elixir copied to clipboard
vectordotdev
:gen_event handler
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.
I tracked it down to a request to :hackney in Timber.HTTPClients.Hackney.
:hackney.request(method, url, req_headers, body, req_opts)
Thanks for filing this. Oh how I dislike hackney, we've wasted so much time debugging it. @mitchellhenke will take a crack at this.
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.
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 - 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}]
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...
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?
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.
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.
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?
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....
You mentioned that it happened on the server, but not locally. Is there a different configuration or something else like that, like deploying with Distillery?
Dang, I tried a release with distillery and was not able to reproduce (I've updated my example repo with it as well). I'm not sure on the next step to debug this 😕
What cloud provider are you deploying to out of curiosity? Amazon? Google? I might try deploying your sample app....
Oh I see, thanks, yes locally I don't have this issue either. It just seems to be an issue in the remote environment. I was hoping it might be a simple config issue, but so far it's looking like it's not. Let me see if I can replicate with your sample application.
@mitchellhenke -
One thing I did now notice - the app that caused this issue (call it App X) had timber requiring "~> hackney 1.9.0" in the mix.lock as a dependency, but there was also a separate line in mix.lock calling for
"hackney": {:hex, :hackney, "1.15.1", "xxxx", [:rebar3], [{:certifi, "2.5.1", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "6.0.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "1.0.1", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "~>1.1", [hex: :mimerl, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "1.1.4", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}], "hexpm"}
I don't know why it's there (and I can change it), but do you know if timber-elixir has been tested to work with hackney 1.15.1 ?
I added that version to my example because your comment here looked like the app was on hackney 1.9.0: https://github.com/timberio/timber-elixir/issues/346#issuecomment-490223218
The example app works for me with hackney 1.9.0 and hackney 1.15.1
yes, thank you @mitchellhenke for bearing with me, in somewhat "better" news, I made a private branch for your example app (I should add I made a few config changes - notably I added an umbrella phoenix app and removed ":console" value from config :logger, backends [Timber.LoggerBackends.HTTP] - can push up a sanitized branch of this if you'd like) and deployed it to Google cloud. I think I found the actual issue that may result in a better bug report on my part that hopefully you may be able to reproduce - the issue occurs on a remote_console. So, to reproduce:
- Start the main elixir application (
sudo bin/kv_umbrella consolewas the command I used after ssh-ing into the cloud instance; the release was built with distillery) - Start a remote console (
sudo bin/kv_umbrella remote_console) and do Logger.info "some msg". - With hackney 1.15.1 specified as an explicit dependency I get the original error message as reported in the initial comment (https://github.com/timberio/timber-elixir/issues/346#issue-439396483)
- With hackney 1.9.0, I get the following error in remote_console:
iex([email protected])3> Logger.info "test hackney 1.9 remote"
:ok
iex([email protected])4> :gen_event handler Timber.LoggerBackends.HTTP installed in Logger terminating
** (exit) exited in: :gen_server.call(:hackney_manager, {:new_request, #PID<0.100.0>, #Reference<0.4163826693.2176581634.159815>, {:client, :undefined, {:metrics_ng, :metrics_dummy}, :hackney_ssl, 'logs.timber.io', 443, "logs.timber.io", [connect_timeout: 5000, recv_timeout: 10000, async: true], nil, nil, nil, true, :hackney_pool, 10000, false, 5, false, 5, nil, nil, nil, {0, {:dict, 0, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], [], [], ...}, {{[], [], [], [], [], [], [], [], [], [], [], [], ...}}}}, :undefined, :start, nil, :normal, false, true, false, :undefined, false, nil, :waiting, nil, 4096, "", [], :undefined, nil, nil, nil, nil, :undefined, nil}}, :infinity)
** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
nil
iex([email protected])5> Application.ensure_all_started(:hackney)
{:ok, []}
iex([email protected])6> Logger.info "test hackney 1.9 remote"
:ok
iex([email protected])7> :gen_event handler Timber.LoggerBackends.HTTP installed in Logger terminating
** (exit) exited in: :gen_server.call(:hackney_manager, {:new_request, #PID<0.100.0>, #Reference<0.4163826693.2176581634.159907>, {:client, :undefined, {:metrics_ng, :metrics_dummy}, :hackney_ssl, 'logs.timber.io', 443, "logs.timber.io", [connect_timeout: 5000, recv_timeout: 10000, async: true], nil, nil, nil, true, :hackney_pool, 10000, false, 5, false, 5, nil, nil, nil, {0, {:dict, 0, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], [], [], ...}, {{[], [], [], [], [], [], [], [], [], [], [], [], ...}}}}, :undefined, :start, nil, :normal, false, true, false, :undefined, false, nil, :waiting, nil, 4096, "", [], :undefined, nil, nil, nil, nil, :undefined, nil}}, :infinity)
** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
nil
iex([email protected])8> Application.started_applications
[
{:mix, 'mix', '1.8.1'},
{:iex, 'iex', '1.8.1'},
{:sasl, 'SASL CXC 138 11', '3.3'},
{:api, 'api', '0.1.0'},
{:kv_server, 'kv_server', '0.1.0'},
{:statix, 'Fast and reliable Elixir client for StatsD-compatible servers.',
'1.1.0'},
{:gettext, 'Internationalization and localization through gettext', '0.16.1'},
{:timber_exceptions,
'Timber\'s exception tracking integration captures Elixir exceptions as\nstructured data in your logs\n',
'2.1.0'},
{:timber_phoenix,
'Timber\'s Phoenix integration provides structured logging for applications\nbuilt with the Phoenix Framework\n',
'1.1.0'},
{:phoenix_html, 'Phoenix view functions for working with HTML templates',
'2.13.2'},
{:timber_ecto,
'Timber\'s Ecto integration logs query operations with structured metadata\n',
'2.1.1'},
{:ecto, 'A toolkit for data mapping and language integrated query for Elixir',
'3.1.4'},
{:decimal, 'Arbitrary precision decimal arithmetic.', '1.7.0'},
{:timber_plug,
'Timber\'s Plug integration logs HTTP events with structured metadata\n',
'1.1.0'},
{:timber,
[127794, 32, 71, 114, 101, 97, 116, 32, 69, 108, 105, 120, 105, 114, 32, 76,
111, 103, 103, 105, 110, 103, 32, 77, 97, 100, 101, 32, 69, 97, 115, 121,
46, ...], '3.1.1'},
{:msgpax,
'This library provides an API for serializing and de-serializing Elixir terms using the MessagePack format.',
'2.2.2'},
{:jason, 'A blazing fast JSON parser and generator in pure Elixir.\n',
'1.1.2'},
{:hackney, 'simple HTTP client', '1.9.0'},
{:idna, 'A pure Erlang IDNA implementation', '5.1.0'},
{:unicode_util_compat, 'unicode_util compatibility library for Erlang < 20',
'0.3.1'},
{:mimerl, 'An OTP library', '1.0.2'},
{:ssl_verify_fun, [], '1.1.1'},
{:metrics, 'A generic interface to different metrics systems in Erlang.',
'1.0.1'},
{:certifi, 'An OTP library', '2.0.0'},
{:phoenix,
'Productive. Reliable. Fast. A productive web framework that\ndoes not compromise speed or maintainability.\n',
'1.4.5'},
{:phoenix_pubsub, 'Distributed PubSub and Presence platform', '1.1.2'},
{:eex, 'eex', '1.8.1'},
{:distillery, 'Build releases of your Mix projects with ease!\n', '2.0.12'},
{:runtime_tools, 'RUNTIME_TOOLS', '1.13.1'},
{:artificery, 'A toolkit for terminal user interfaces in Elixir', '0.4.1'},
{:plug_cowboy, 'A Plug adapter for Cowboy', '2.0.2'},
{:plug,
'A specification and conveniences for composable modules between web applications',
'1.8.0'},
{:mime, 'A MIME type module for Elixir', '1.3.1'},
{:logger, 'logger', '1.8.1'},
{:cowboy, 'Small, fast, modern HTTP server.', '2.6.3'},
{:cowlib, 'Support library for manipulating Web protocols.', '2.7.3'},
{:ranch, 'Socket acceptor pool for TCP protocols.', '1.7.1'},
{:ssl, 'Erlang/OTP SSL application', '9.1.2'},
{:public_key, 'Public key infrastructure', '1.6.4'},
{:asn1, 'The Erlang ASN1 compiler version 5.0.8', '5.0.8'},
{:plug_crypto, 'Crypto-related functionality for the web, used by Plug.',
'1.0.0'},
{:elixir, 'elixir', '1.8.1'},
{:compiler, 'ERTS CXC 138 10', '7.3.1'},
{:crypto, 'CRYPTO', '4.4'},
{:stdlib, 'ERTS CXC 138 10', '3.7.1'},
{:kernel, 'ERTS CXC 138 10', '6.2'}
]
Note: I'm including some of the basic troubleshooting things I did in console as well.
Let me know if you can think of anything else I can do to help that would make troubleshooting on your end easier. Can provide the google cloud machine type, etc.
@mitchellhenke - just made the PR to document the workaround I came up with at the moment.
@treble37 if I understand correctly, your PR does not solve the issue only covers it so there is no exception thrown. The requests still fail.
Have you found the solution to this problem? I have precisely the same issue...
@hubertlepicki, unfortunately, I haven't come up with something better. You still can't seem to issue Logger requests from a remote_console. Fortunately, timber logging in a non-remote context seems to work (ie, works from the app I'm running). I think one of the timber contributors said somewhere they were going to remove hackney at some point as it has given them a bit of trouble.
I believe I'm seeing a similar issue when trying to stop my app, which was started from Distillery. It causes the app to fail to stop cleanly, and I end up having to kill the beam app and related processes.
23:58:26.603 [error] :gen_event handler Timber.LoggerBackends.HTTP installed in Logger terminating
** (ArgumentError) argument error
(stdlib) :ets.lookup_element(:hackney_config, :mod_metrics, 2)
(hackney) /builds/intrinsicfinance/intrinsic_x_umbrella/deps/hackney/src/hackney_metrics.erl:27: :hackney_metrics.get_engine/0
(hackney) /builds/intrinsicfinance/intrinsic_x_umbrella/deps/hackney/src/hackney_connect.erl:78: :hackney_connect.create_connection/5
(hackney) /builds/intrinsicfinance/intrinsic_x_umbrella/deps/hackney/src/hackney_connect.erl:47: :hackney_connect.connect/5
(hackney) /builds/intrinsicfinance/intrinsic_x_umbrella/deps/hackney/src/hackney.erl:330: :hackney.request/5
(timber) lib/timber/logger_backends/http.ex:336: Timber.LoggerBackends.HTTP.issue_request/1
(timber) lib/timber/logger_backends/http.ex:178: Timber.LoggerBackends.HTTP.handle_info/2
(stdlib) gen_event.erl:577: :gen_event.server_update/4
We have the same issue and it makes it impossible to create a remote_console on the distillery release and run ad-hoc functions that log anything.
Seeing the same issue:
iex([email protected])3> Logger.info("test from prod")
2019-11-14 15:51:23.373 [info] test from prod
:ok
iex([email protected])4> 2019-11-14 15:51:23.742 [error] :gen_event handler Timber.LoggerBackends.HTTP installed in Logger terminating
** (ArgumentError) argument error
(stdlib) :ets.lookup_element(:hackney_config, :mod_metrics, 2)
(hackney) /builds/skoach/skoach-bot/deps/hackney/src/hackney_metrics.erl:26: :hackney_metrics.get_engine/0
(hackney) /builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl:78: :hackney_connect.create_connection/5
(hackney) /builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl:47: :hackney_connect.connect/5
(hackney) /builds/skoach/skoach-bot/deps/hackney/src/hackney.erl:333: :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
Last message: :flush
2019-11-14 15:51:23.744 [error] GenServer #PID<0.107.0> terminating
** (stop) {:EXIT, {:badarg, [{:ets, :lookup_element, [:hackney_config, :mod_metrics, 2], []}, {:hackney_metrics, :get_engine, 0, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_metrics.erl', line: 26]}, {:hackney_connect, :create_connection, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl', line: 78]}, {:hackney_connect, :connect, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl', line: 47]}, {:hackney, :request, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney.erl', line: 333]}, {Timber.LoggerBackends.HTTP, :transmit_buffer, 2, [file: 'lib/timber/logger_backends/http.ex', line: 396]}, {Timber.LoggerBackends.HTTP, :handle_info, 2, [file: 'lib/timber/logger_backends/http.ex', line: 211]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}]}}
Last message: {:gen_event_EXIT, Timber.LoggerBackends.HTTP, {:EXIT, {:badarg, [{:ets, :lookup_element, [:hackney_config, :mod_metrics, 2], []}, {:hackney_metrics, :get_engine, 0, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_metrics.erl', line: 26]}, {:hackney_connect, :create_connection, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl', line: 78]}, {:hackney_connect, :connect, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney_connect.erl', line: 47]}, {:hackney, :request, 5, [file: '/builds/skoach/skoach-bot/deps/hackney/src/hackney.erl', line: 333]}, {Timber.LoggerBackends.HTTP, :transmit_buffer, 2, [file: 'lib/timber/logger_backends/http.ex', line: 396]}, {Timber.LoggerBackends.HTTP, :handle_info, 2, [file: 'lib/timber/logger_backends/http.ex', line: 211]}, {:gen_event, :server_update, 4, [file: 'gen_event.erl', line: 577]}]}}}
On elixir 1.9, timber 3.1.2.
Can confirm. Timber logging works when in iex , but not when using releases built by distillery and in remote_console
