Skip to content

Instantly share code, notes, and snippets.

@binarytemple-clients

binarytemple-clients/Dbg.markdown

Last active March 28, 2016 20:04
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save binarytemple-clients/2c8ff8928cd9c6589994 to your computer and use it in GitHub Desktop.
Save binarytemple-clients/2c8ff8928cd9c6589994 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
Dbg.markdown

Start the Dbg application

iex(6)> Application.start(:dbg)
{:error, {:not_started, :runtime_tools}}
iex(7)> Application.start(:runtime_tools)
:ok
iex(8)> Application.start(:dbg)
:ok

Putting a watch a single function within hackney, then setting a trace:

iex(9)> Dbg.call(&:hackney.request/5)
%{counts: %{nonode@nohost: 1}, errors: %{}}
iex(10)> Dbg.trace(self(),[:call])
%{counts: %{nonode@nohost: 1}, errors: %{}}

Watching the entire hackney module, then setting a trace:

iex(9)> Dbg.call(:hackney)
%{counts: %{nonode@nohost: 1}, errors: %{}}
iex(10)> Dbg.trace(self(),[:call])
%{counts: %{nonode@nohost: 1}, errors: %{}}

Lets wrap all that initialization into a single anonymous function:

x = fn() -> 
Application.start(:runtime_tools)
Application.start(:dbg)
Dbg.call(:hackney)
Dbg.trace(self(),[:call])
end

We can invoke it like so:

iex(3)> x.()
%{counts: %{nonode@nohost: 1}, errors: %{}}

Could we wrap the two together? This reminds me a little of JavaScript

iex(5)> ((fn() ->
...(5)> Application.start(:runtime_tools)
...(5)> Application.start(:dbg)
...(5)> Dbg.call(:hackney)
...(5)> Dbg.trace(self(),[:call])
...(5)> end).())

** (Dbg) #PID<0.293.0> calls :hackney.module_info/0 with arguments:
    []
%{counts: %{nonode@nohost: 1}, errors: %{}}

Tracing all events on self() not a great idea

iex(16)> Dbg.trace(self(),[:all])
%{counts: %{nonode@nohost: 1}, errors: %{}}
iex(17)>
** (Dbg) #PID<0.493.0> (at 14:04:00) receives:
    {:dbg, {:ok, [{:matched, :nonode@nohost, 1}]}}

** (Dbg) #PID<0.493.0> (at 14:04:00) schedules in with :dbg.req/1

** (Dbg) #PID<0.493.0> (at 14:04:00) sends to #PID<0.26.0>:
    {:io_request, #PID<0.493.0>, #Reference<0.0.1.4945>, {:get_geometry, :columns}}

** (Dbg) #PID<0.493.0> (at 14:04:00) schedules out with :io.execute_request/2

...... ad nauseum

Stop that silliness by calling Dgb.clear

** (Dbg) #PID<0.493.0> (at 14:04:57) receives:
    {:eval, #PID<0.27.0>, "Dbg.clear\n", %IEx.State{cache: [], counter: 27, prefix: "iex"}}
%{counts: %{nonode@nohost: 1}, errors: %{}}

** (Dbg) #PID<0.493.0> (at 14:04:57) schedules in with IEx.Evaluator.loop/3
iex(28)>
** (Dbg) #PID<0.493.0> (at 14:04:57) starts garbage collecting:
    [old_heap_block_size: 4185, heap_block_size: 2586, mbuf_size: 0, recent_size: 784, stack_size: 39, old_heap_size: 856, heap_size: 2545, bin_vheap_size: 4, bin_vheap_block_size: 46422, bin_old_vheap_size: 0, bin_old_vheap_block_size: 46422]

..... etc.. eventually stops flooding the terminal.

Unsure what the significance of local_call is, but calls to hackney module are producing trace.

I've trimmed the output to concentrate on the most interesting aspects:

iex(31)> Dbg.local_call(:hackney)
%{counts: %{nonode@nohost: 169}, errors: %{}}
iex(32)>
nil
iex(33)> Dbg.trace(self(),[:call , :return_to])
%{counts: %{nonode@nohost: 1}, errors: %{}}

iex(34)> :hackney.get("http://www.google.com")

** (Dbg) #PID<0.493.0> calls :hackney.get/1 with arguments:
    ["http://www.google.com"]

** (Dbg) #PID<0.493.0> calls :hackney.request/2 with arguments:
    [:get, "http://www.google.com"]

** (Dbg) #PID<0.493.0> calls :hackney.request/5 with arguments:
    [:get, "http://www.google.com", [], "", []]

** (Dbg) #PID<0.493.0> calls :hackney.request/5 with arguments:
    [:get, {:hackney_url, :hackney_tcp_transport, :http, "www.google.com", "/", "/", "", "", 'www.google.com', 80, "", ""}, [], "", []]

** (Dbg) #PID<0.493.0> calls :hackney.maybe_redirect/2 with arguments:
    [{:ok, 302, [{"Cache-Control", "private"}, {"Content-Type", "text/html; charset=UTF-8"}, {"Location", "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB"}, {"Content-Length", "259"}, {"Date", "Mon, 28 Mar 2016 13:07:23 GMT"}], {:client, {1459, 170442, 972255}, :hackney_dummy_metrics, :hackney_tcp_transport, 'www.google.com', 80, "www.google.com", [], #Port<0.20141>, {:default, #Reference<0.0.1.6698>, {'www.google.com', 80, :hackney_tcp_transport}, #PID<0.523.0>, :hackney_tcp_transport}, #Reference<0.0.1.6698>, true, :hackney_pool, 5000, false, 5, false, 5, nil, "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB", {:hparser, :response, 4096, 10, 0, :on_body, "<HTML><HEAD><meta http-equiv=\"content-type\" content=\"text/html;charset=utf-8\">\n<TITLE>302 Moved</TITLE></HEAD><BODY>\n<H1>302 Moved</H1>\nThe document has moved\n<A HREF=\"http://www.google.co.uk/?gfe_rd=cr&amp;ei=iyz5Vt-vAdXDaOaamrgB\">here</A>.\r\n</BODY></HTML>\r\n", {1, 1}, :undefined, [], 259, :undefined, :undefined, "text/html; charset=utf-8", "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB", :waiting}, :connected, :waiting, nil, :normal, false, false, false, :undefined, false, &:hackney_request.send/2, :waiting, nil, 4096, "", [], {1, 1}, 259, nil, nil, "GET", "/", "text/html; charset=UTF-8"}}, {:get, "/", [{"Host", "www.google.com"}], ""}]

** (Dbg) #PID<0.493.0> returns to :hackney.send_request/2

** (Dbg) #PID<0.493.0> calls :hackney.reply_response/2 with arguments:
    [{:ok, 302, [{"Cache-Control", "private"}, {"Content-Type", "text/html; charset=UTF-8"}, {"Location", "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB"}, {"Content-Length", "259"}, {"Date", "Mon, 28 Mar 2016 13:07:23 GMT"}], {:client, {1459, 170442, 972255}, :hackney_dummy_metrics, :hackney_tcp_transport, 'www.google.com', 80, "www.google.com", [], #Port<0.20141>, {:default, #Reference<0.0.1.6698>, {'www.google.com', 80, :hackney_tcp_transport}, #PID<0.523.0>, :hackney_tcp_transport}, #Reference<0.0.1.6698>, true, :hackney_pool, 5000, false, 5, false, 5, nil, "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB", {:hparser, :response, 4096, 10, 0, :on_body, "<HTML><HEAD><meta http-equiv=\"content-type\" content=\"text/html;charset=utf-8\">\n<TITLE>302 Moved</TITLE></HEAD><BODY>\n<H1>302 Moved</H1>\nThe document has moved\n<A HREF=\"http://www.google.co.uk/?gfe_rd=cr&amp;ei=iyz5Vt-vAdXDaOaamrgB\">here</A>.\r\n</BODY></HTML>\r\n", {1, 1}, :undefined, [], 259, :undefined, :undefined, "text/html; charset=utf-8", "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB", :waiting}, :connected, :waiting, nil, :normal, false, false, false, :undefined, false, &:hackney_request.send/2, :waiting, nil, 4096, "", [], {1, 1}, 259, nil, nil, "GET", "/", "text/html; charset=UTF-8"}}, {:client, {1459, 170442, 972255}, :hackney_dummy_metrics, :hackney_tcp_transport, 'www.google.com', 80, "www.google.com", [], #Port<0.20141>, {:default, #Reference<0.0.1.6698>, {'www.google.com', 80, :hackney_tcp_transport}, #PID<0.523.0>, :hackney_tcp_transport}, #Reference<0.0.1.6698>, true, :hackney_pool, 5000, false, 5, false, 5, nil, nil, nil, :connected, :start, nil, :normal, false, false, false, :undefined, false, nil, :waiting, nil, 4096, "", [], :undefined, nil, nil, nil, nil, :undefined, nil}]

** (Dbg) #PID<0.493.0> returns to :erl_eval.do_apply/6
{:ok, 302,
 [{"Cache-Control", "private"}, {"Content-Type", "text/html; charset=UTF-8"},
  {"Location", "http://www.google.co.uk/?gfe_rd=cr&ei=iyz5Vt-vAdXDaOaamrgB"},
  {"Content-Length", "259"}, {"Date", "Mon, 28 Mar 2016 13:07:23 GMT"}],
 #Reference<0.0.1.6698>}
iex(35)> :hackney.get("http://www.google.com")

So the problem is, when I call hackney from the console, the method calls are fully traced, but it isn't producing trace output for invocation withing the oauth2_example application.

As a first step towards resolution, I recompile the project dependencies, adding debugging info:

 mix deps.compile --debug-info

TO BE CONTINUED....

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment