[erlang-questions] No backtrace on errors in cowboy
Aleksandr Vinokurov
aleksandr.vin@REDACTED
Wed Jul 18 05:37:00 CEST 2012
Thanks, Fred
That describe everything. Wish I suggested tail recursion yesterday.
-- Aleksandr
18.07.2012, в 6:34, Fred Hebert <mononcqc@REDACTED> написал(а):
> 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\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/20120718/c2102ffb/attachment.htm>
More information about the erlang-questions
mailing list