[erlang-questions] No backtrace on errors in cowboy
Fred Hebert
mononcqc@REDACTED
Wed Jul 18 04:34:57 CEST 2012
First of all, you have to understand that when a request comes in
cowboy, there goes a chain of command based on how you described your
listener in a call to cowboy:start_listener. That chain does things like
accepting requests, handling socket/port ownership, and dispatching stuff.
One of the steps in there is to start a process based on the protocol
you picked. In this case, the protocol is handled by
cowboy_http_protocol, and the function is request.
That's where your stack trace begins.
When a call is made in Erlang, and that call is the last thing to happen
in a function's body (it's a tail call), the stack trace for the current
one will be dropped. This is to say, if I have:
a() -> b(), ok.
b() -> hello, c().
c() -> ok.
and I'm in b(), the stack trace will be [a, b]. a() is there because b()
isn't happening in last place. We thus need to store that we're part of
'a' in order to return to it in the future and execute the 'ok'
expression. Then b() calls c().
Because b() ends with a call to c(), and we know that b() returns to
a(), we can replace b in [a,b] and change it to [a,c]. This is good,
because when we do things like recursing forever in a server loop, it
keeps us from growing the stack until it crashes (stack overflow, or
OOM). We drop whatever stack trace information we can afford to drop.
So when your error happens, it's on line 172.
This goes through:
request -> parse_header -> wait_header
parse_header and wait_header both happen in a tail position. This
explains why your stack trace shows *nothing* but request. They're each
removed from the stack trace before. That explains why you get:
[{cowboy_http_protocol,request,2,
[{file,"src/cowboy_http_protocol.erl"},{line,172}]}]
Consider yourself lucky we now have line numbers to help!
Now for the shell, when you get an error there, it looks like:
[{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,576}]},
{erl_eval,try_clauses,8,[{file,"erl_eval.erl"},{line,767}]},
{shell,exprs,7,[{file,"shell.erl"},{line,668}]},
{shell,eval_exprs,7,[{file,"shell.erl"},{line,623}]},
{shell,eval_loop,3,[{file,"shell.erl"},{line,608}]}]
This is simply because shell evaluation and whatnot, for all these
functions, is *not* making these calls in a tail position. This is part
of how the shell works, and explains why you'll get a longer stack trace
there than with compiled code.
You can see part of the variation there:
1> spawn(fun() -> try
1> erlang:error(xxxxxREQ_error)
1> catch
1> error:_ ->
1> io:format("~nxxxxxREQ_error stacktrace~n~p~n",
[erlang:get_stacktrace()])
1> end
1> end).
xxxxxREQ_error stacktrace
[{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,576}]},
{erl_eval,try_clauses,8,[{file,"erl_eval.erl"},{line,767}]}]
<0.71.0>
You'll see that for that one, part of the evaluation was done
beforehand. When the new function is spawned and starts running, the
'shell' module is no longer involved, and the stack trace changes. New
processes do not carry old stack information as they need not to return
anywhere.
So it's not surprising that you get barely nothing from cowboy when the
function you get is pretty much the only one that can be allowed in the
stack trace by these rules. It's brand new and the error happens after a
chain of tail calls.
I hope this helps.
On 12-07-17 2:09 PM, Aleksandr Vinokurov wrote:
>
>
> Hello all,
>
> I need to see a backtrace of a cowboy_http_protocol:request/2 and to
> get it I've added some code in the function (marked strong):
>
> request(_Any, State) ->
> %%%%%%%%%
> *io:format("~n~p~n", [{xxxxx161, State, _Any}]),*
> * try*
> * erlang:error(xxxxx161_error)*
> * catch*
> * error:X ->*
> * io:format("~nxxxxx161_error stacktrace~n~p~n",
> [erlang:get_stacktrace()]),*
> * erlang:error(X)*
> * end,*
> *%%%%%%%%%%%*
> error_terminate(400, State).
>
>
> After recompilation and reloading I see only one line in backtrace list:
>
> (web@REDACTED)1>
> {xxxxx161,
> {state,<0.85.0>,#Port<0.3809>,cowboy_tcp_transport,
> [{'_',
> [{[<<"token">>],
> ps_oauth_2_api_external_token_endpoint,
> [{config,off,off,
> {{127,0,0,1},8080},
> {{127,0,0,1},8180},
> {{127,0,0,1},8443},
> {{127,0,0,1},8543},
> [{"jay","123"},"bob",{"matt","321"}],
> "http://127.0.0.1:8881/client-storage",
> [{<<"apt1">>,{seconds,600,"600"}},
> {<<"apt2">>,{seconds,6000,"6000"}}],
> {seconds,3600,"3600"},
> {seconds,600,"600"},
> undefined,
> {bytes,64},
> {bytes,256},
> {bytes,1024}},
> {external_api_applications,ps_oauth_2_ext_api_applications}]},
> {'_',ps_oauth_2_index,[external,#Fun<ps_oauth_2.2.99090327>]}]}],
> {ps_oauth_2_api_external_token_endpoint,
> [{config,off,off,
> {{127,0,0,1},8080},
> {{127,0,0,1},8180},
> {{127,0,0,1},8443},
> {{127,0,0,1},8543},
> [{"jay","123"},"bob",{"matt","321"}],
> "http://127.0.0.1:8881/client-storage",
> [{<<"apt1">>,{seconds,600,"600"}},
> {<<"apt2">>,{seconds,6000,"6000"}}],
> {seconds,3600,"3600"},
> {seconds,600,"600"},
> undefined,
> {bytes,64},
> {bytes,256},
> {bytes,1024}},
> {external_api_applications,ps_oauth_2_ext_api_applications}]},
> undefined,undefined,
> {#Fun<cowboy_http.urldecode.2>,crash},
> 0,5,213,infinity,4096,5000,
> <<"authorization: Basic YXBwMToxMjM=\r\nconnection:
> keep-alive\r\n\r\ngrant_type=authorization_code&code=1pD8tsKZTFXw3sbbOPbLtCU0oSg5CWx%2FohR8AC%2BAuTROzsx1DQC6LLm4h6iaOvupV5cOs3cAqBqsWB%2BtzfxVtg%3D%3D">>,
> false,infinity,undefined},
> {http_error,<<"7.0.0.1:8080 <http://7.0.0.1:8080>\r\n">>}}
>
> (web@REDACTED)1>
> xxxxx161_error stacktrace
> [{cowboy_http_protocol,request,2,
> [{file,"src/cowboy_http_protocol.erl"},{line,172}]}]
> (web@REDACTED)1>
>
> =ERROR REPORT==== 17-Jul-2012::21:51:26 ===
> Error in process <0.1373.0> on node 'web@REDACTED' with exit value:
> {xxxxx161_error,[{cowboy_http_protocol,request,2,[{file,"src/cowboy_http_protocol.erl"},{line,176}]}]}
>
> =SUPERVISOR REPORT==== 17-Jul-2012::21:51:26 ===
> Supervisor: {<0.86.0>,cowboy_requests_sup}
> Context: child_terminated
> Reason: {xxxxx161_error,
> [{cowboy_http_protocol,request,2,
> [{file,"src/cowboy_http_protocol.erl"},
> {line,176}]}]}
> Offender: [{pid,<0.1373.0>},
> {name,cowboy_requests_sup},
> {mfargs,{cowboy_requests_sup,start_request,undefined}},
> {restart_type,temporary},
> {shutdown,brutal_kill},
> {child_type,worker}]
>
> If I call that code in shell I see a full backtrace like that:
>
> (web@REDACTED)4> try
> erlang:error(xxxxxREQ_error)
> catch
> error:_ ->
> io:format("~nxxxxxREQ_error stacktrace~n~p~n",
> [erlang:get_stacktrace()])
> end.
>
> xxxxxREQ_error stacktrace
> [{erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,576}]},
> {erl_eval,try_clauses,8,[{file,"erl_eval.erl"},{line,767}]},
> {shell,exprs,7,[{file,"shell.erl"},{line,668}]},
> {shell,eval_exprs,7,[{file,"shell.erl"},{line,623}]},
> {shell,eval_loop,3,[{file,"shell.erl"},{line,608}]}]
> ok
> (web@REDACTED)5>
>
> I don't understand what am I doing wrong.
>
> --
> ????????? ?????????
> +7 (921) 982-21-43
> @aleksandrvin
>
>
>
> _______________________________________________
> erlang-questions mailing list
> erlang-questions@REDACTED
> http://erlang.org/mailman/listinfo/erlang-questions
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20120717/85d5c4f1/attachment.htm>
More information about the erlang-questions
mailing list