From 5b3a8f7a8b1f428ef103f5e9a9de13bcae1618c4 Mon Sep 17 00:00:00 2001 From: Christopher Piro Date: Wed, 1 Aug 2007 22:27:37 +0000 Subject: [PATCH] [thrift] improved error logging and handling for Erlang bindings Summary: * custom, extensible error logger -- show only relevant stuff * clean up of errors in developer-supplied handler module now gives sane error messages and doesn't crash whole server (introduces tApplicationException_HANDLER_ERROR) * more precise catch in tErlProcessor (exits gracefully only if transport closes) Reviewed By: iproctor Test Plan: tutorial works Revert Plan: ok git-svn-id: https://svn.apache.org/repos/asf/incubator/thrift/trunk@665186 13f79535-47bb-0310-9956-ffa450edef68 --- compiler/cpp/src/generate/t_erl_generator.cc | 46 ++- lib/erl/lib/thrift/TODO | 28 +- .../thrift/include/tApplicationException.hrl | 1 + lib/erl/lib/thrift/include/thrift.hrl | 5 + lib/erl/lib/thrift/include/thrift_logger.hrl | 7 + lib/erl/lib/thrift/server.sh | 2 +- lib/erl/lib/thrift/src/oop.erl | 72 +++-- lib/erl/lib/thrift/src/server/tErlServer.erl | 9 +- .../lib/thrift/src/server/tSimpleServer.erl | 15 +- lib/erl/lib/thrift/src/tErlProcessor.erl | 3 +- lib/erl/lib/thrift/src/thrift.erl | 25 ++ lib/erl/lib/thrift/src/thrift_logger.erl | 282 ++++++++++++++++++ lib/erl/lib/thrift/src/thrift_oop_server.erl | 55 ++-- lib/erl/lib/thrift/src/thrift_utils.erl | 51 +++- .../lib/thrift/src/transport/tErlAcceptor.erl | 178 +++-------- lib/erl/lib/thrift/src/transport/tSocket.erl | 7 +- .../lib/thrift/src/transport/tTransport.erl | 2 +- tutorial/erl/server.erl | 31 +- 18 files changed, 606 insertions(+), 213 deletions(-) create mode 100644 lib/erl/lib/thrift/include/thrift_logger.hrl create mode 100644 lib/erl/lib/thrift/src/thrift.erl create mode 100644 lib/erl/lib/thrift/src/thrift_logger.erl diff --git a/compiler/cpp/src/generate/t_erl_generator.cc b/compiler/cpp/src/generate/t_erl_generator.cc index 5779078b..1b3e7cfd 100644 --- a/compiler/cpp/src/generate/t_erl_generator.cc +++ b/compiler/cpp/src/generate/t_erl_generator.cc @@ -764,6 +764,7 @@ void t_erl_generator::generate_service_client(t_service* tservice) { indent() << " throw(X);" << endl << indent() << " true ->" << endl << indent() << " Result = " << resultname << "_read(Iprot)," << endl << + indent() << " Result, % suppress unused warnings" << endl << indent() << " ?R0(Iprot, readMessageEnd)," << endl << indent() << " if % time to figure out retval" << endl; @@ -960,6 +961,9 @@ void t_erl_generator::generate_process_function(t_service* tservice, const std::vector& fields = arg_struct->get_members(); vector::const_iterator f_iter; + indent(f_service_) << "try" << endl; + indent_up(); + indent(f_service_) << "Result = "; if (xceptions.size() > 0) { f_service_ << "try" << endl; @@ -1004,18 +1008,46 @@ void t_erl_generator::generate_process_function(t_service* tservice, } indent(f_service_) << "end," << endl; - if (tfunction->is_async()) { - indent(f_service_) << "% async, write nothing" << endl; - } else { + if (!tfunction->is_async()) { f_service_ << indent() << "?R3(Oprot, writeMessageBegin, \"" << tfunction->get_name() << "\", ?tMessageType_REPLY, Seqid)," << endl << - indent() << tfunction->get_name() << "_result_write(Result, Oprot)," << endl << - indent() << "?R0(Oprot, writeMessageEnd)," << endl << + indent() << tfunction->get_name() << "_result_write(Result, Oprot)," << endl; + } + indent(f_service_) << "Result" << endl; + indent_down(); + + // catch errors in the handler + indent(f_service_) << "catch" << endl << + indent() << " _:Kind when Kind == undef; Kind == function_clause ->" << endl << + indent() << " X = tApplicationException:new(?tApplicationException_HANDLER_ERROR, \"Handler doesn't implement " + << tfunction->get_name() <<"\")," << endl << + + indent() << " ?R3(Oprot, writeMessageBegin, \"" << tfunction->get_name() << "\", ?tMessageType_EXCEPTION, Seqid)," << endl << + indent() << " tApplicationException:write(X, Oprot)," << endl << + indent() << " {error, X};" << endl << + indent() << " _:_Kind ->" << endl << + indent() << " X = tApplicationException:new(?tApplicationException_HANDLER_ERROR, \"Unknown handler error in " + << tfunction->get_name() << "\")," << endl << + + indent() << " ?R3(Oprot, writeMessageBegin, \"" << tfunction->get_name() << "\", ?tMessageType_EXCEPTION, Seqid)," << endl << + indent() << " tApplicationException:write(X, Oprot)," << endl << + indent() << " {error, X}" << endl; + + // 'after' block if we're expecting a result written + if (!tfunction->is_async()) { + f_service_ << + indent() << "after" << endl; + + indent_up(); + + indent(f_service_) << "?R0(Oprot, writeMessageEnd)," << endl << indent() << "Trans = ?R1(Oprot, get, trans)," << endl << - indent() << "?R0(Trans, effectful_flush)," << endl; + indent() << "?R0(Trans, effectful_flush)" << endl; + + indent_down(); } - indent(f_service_) << "Result." << endl << endl; + indent(f_service_) << "end." << endl; indent_down(); } diff --git a/lib/erl/lib/thrift/TODO b/lib/erl/lib/thrift/TODO index e2a870d7..1ca21843 100644 --- a/lib/erl/lib/thrift/TODO +++ b/lib/erl/lib/thrift/TODO @@ -1,10 +1,36 @@ +make thrift a proper OTP application + * app-wide configuration (do DNS lookups?) + * default protocols / transports (forget this factory business) + * factor for elegance + tutorial client find TODO(cpiro)s make all methods effectful, remove the special casing (optionally, implement monads for Erlang) -inheritance +change objects from {record_tag, ...} to {oop_object, {record_tag, ...}, other_useful_stuff} +so 1) we know exactly what's an object (can write is_object/1) e.g. + is the tuple {tTransportException, ...} an object or a tuple that happens to start with that atom? + we can't check this using is_record/2 without include every header file + also, this makes it easy to pick objects out of deep tuples + 2) we can build more functionality into oop later if need be + carry around the class/superclasses so is_a(Object, ClassOrSuperclass) is easy + 3) maybe hack up io:format and friends to run objects through oop:inspect automatically test suites +move as much as possible out of thrift_logger + +make thrift_logger 100% robust + +thrift_logger detects term width? + undisgustify codegen + +move away from thrift_oop_server shim to straight-up gen_servers + +move away from Factories + +move away from ?L0, ?M0, and friends ... make calls in oop +better/worse yet, make an absyn transformer and introduce some slick syntax to make it less painful and more obvious what's going on +ONLY IF our gentle nudging away from oop and thrift_oop_server isn't good enough diff --git a/lib/erl/lib/thrift/include/tApplicationException.hrl b/lib/erl/lib/thrift/include/tApplicationException.hrl index e2f15384..db7ec2ff 100644 --- a/lib/erl/lib/thrift/include/tApplicationException.hrl +++ b/lib/erl/lib/thrift/include/tApplicationException.hrl @@ -11,5 +11,6 @@ -define(tApplicationException_WRONG_METHOD_NAME, 3). -define(tApplicationException_BAD_SEQUENCE_ID, 4). -define(tApplicationException_MISSING_RESULT, 5). +-define(tApplicationException_HANDLER_ERROR, 6). -record(tApplicationException, {super, type}). diff --git a/lib/erl/lib/thrift/include/thrift.hrl b/lib/erl/lib/thrift/include/thrift.hrl index b47fd390..3be2f686 100644 --- a/lib/erl/lib/thrift/include/thrift.hrl +++ b/lib/erl/lib/thrift/include/thrift.hrl @@ -4,6 +4,11 @@ %%% See accompanying file LICENSE or visit the Thrift site at: %%% http://developers.facebook.com/thrift/ +-define(ERROR(F, D), + error_logger:format(F, D)). +-define(INFO(Type, Report), + error_logger:info_report({thrift_info, Type}, Report)). + % local (same process) -define(L0(Method), oop:call(This, Method, [])). -define(L1(Method, Arg1), oop:call(This, Method, [Arg1])). diff --git a/lib/erl/lib/thrift/include/thrift_logger.hrl b/lib/erl/lib/thrift/include/thrift_logger.hrl new file mode 100644 index 00000000..3f5d7a97 --- /dev/null +++ b/lib/erl/lib/thrift/include/thrift_logger.hrl @@ -0,0 +1,7 @@ +%%% Copyright (c) 2007- Facebook +%%% Distributed under the Thrift Software License +%%% +%%% See accompanying file LICENSE or visit the Thrift site at: +%%% http://developers.facebook.com/thrift/ + +-record(thrift_logger_state, {term_width, force_one_line, omit, gen_server_messages, lookup}). diff --git a/lib/erl/lib/thrift/server.sh b/lib/erl/lib/thrift/server.sh index 0ea4a6b2..03e2fe48 100755 --- a/lib/erl/lib/thrift/server.sh +++ b/lib/erl/lib/thrift/server.sh @@ -8,4 +8,4 @@ fi echo "Compiling user/ and tutorial/gen-erl/..." mkdir ebin-user erlc -I include -I tutorial/gen-erl -o ebin-user user/*.erl tutorial/gen-erl/*.erl && -erl -pa ebin -pa ebin-user -s application start thrift # -s nh start +erl +K true -pa ebin -pa ebin-user diff --git a/lib/erl/lib/thrift/src/oop.erl b/lib/erl/lib/thrift/src/oop.erl index 3e6da054..e3685eea 100644 --- a/lib/erl/lib/thrift/src/oop.erl +++ b/lib/erl/lib/thrift/src/oop.erl @@ -6,9 +6,10 @@ -module(oop). --export([get/2, set/3, call/2, call/3, inspect/1, start_new/2]). +-export([get/2, set/3, call/2, call/3, inspect/1, start_new/2, is_object/1, class/1]). -export([behaviour_info/1]). +-include("thrift.hrl"). -include("oop.hrl"). %%% @@ -77,8 +78,19 @@ get_superobject(Obj) -> none end. +is_object(Obj) when is_tuple(Obj) -> + try + (?CLASS(Obj)):super(), %% if it's an object its first element will be a class name, and it'll have super/0 + true + catch + error:Kind when Kind == undef; Kind == function_clause -> + false + end; +is_object(_) -> + false. + call(Obj, Method, ArgsProper) -> - %% io:format("call called: Obj=~p Method=~p ArgsProper=~p~n", [oop:inspect(Obj), Method, ArgsProper]), + %% error_logger:info_msg("call called: Obj=~p Method=~p ArgsProper=~p", [inspect(Obj), Method, ArgsProper]), Args = [Obj|ArgsProper], %% prepend This to args TryModule = ?CLASS(Obj), call_loop(Obj, Method, Args, TryModule, [], Obj). @@ -88,7 +100,7 @@ call(Obj, Method) -> call_loop(Obj, Method, Args, TryModule, TriedRev, FirstObj) -> try - %% io:format("call_loop~n ~p~n ~p~n ~p~n ~p~n ~n", [inspect(Obj), Method, Args, TryModule]), + %% error_logger:info_msg("call_loop~n ~p~n ~p~n ~p~n ~p", [inspect(Obj), Method, Args, TryModule]), apply(TryModule, Method, Args) catch error:Kind when Kind == undef; Kind == function_clause -> @@ -121,26 +133,52 @@ call_loop(Obj, Method, Args, TryModule, TriedRev, FirstObj) -> end end. +class(Obj) when is_tuple(Obj) -> + case is_object(Obj) of + true -> + ?CLASS(Obj); + false -> + none + end; +class(_) -> + none. + +%% careful: not robust against records beginning with a class name +%% (note: we can't just guard with is_record(?CLASS(Obj), Obj) since we +%% can't/really really shouldn't require all record definitions in this file inspect(Obj) -> - DeepList = inspect_loop(Obj, "#<"), - lists:flatten(DeepList). + try + case is_object(Obj) of + true -> + DeepList = inspect_loop(Obj, "#<"), + lists:flatten(DeepList); + false -> + thrift_utils:sformat("~p", [Obj]) + end + catch + _:E -> + thrift_utils:sformat("INSPECT_ERROR(~p) ~p", [E, Obj]) + + %% TODO(cpiro): bring this back once we're done testing: + %% _:E -> thrift_utils:sformat("~p", [Obj]) + end. inspect_loop(Obj, Str) -> - New = - atom_to_list(?CLASS(Obj)) ++ - ": " ++ - (?CLASS(Obj)):inspect(Obj), - + Class = ?CLASS(Obj), + Inspect = Class:inspect(Obj), + Current = atom_to_list(Class) ++ ": " ++ Inspect, + case get_superobject(Obj) of { ok, Superobj } -> - inspect_loop(Superobj, Str ++ New ++ " | "); + inspect_loop(Superobj, Str ++ Current ++ " | "); none -> - Str ++ New ++ ">" + Str ++ Current ++ ">" end. - + %% TODO: voids take only ok as return? +start_new(none=Resv, _) -> + error_logger:format("can't instantiate ~p: class name is a reserved word", [Resv]), + error; start_new(Class, Args) -> - case gen_server:start_link(thrift_oop_server, {Class, Args}, []) of - {ok, Pid} -> - Pid - end. + {ok, Pid} = gen_server:start_link(thrift_oop_server, {Class, Args}, []), + Pid. diff --git a/lib/erl/lib/thrift/src/server/tErlServer.erl b/lib/erl/lib/thrift/src/server/tErlServer.erl index 8a94709c..0e61e380 100644 --- a/lib/erl/lib/thrift/src/server/tErlServer.erl +++ b/lib/erl/lib/thrift/src/server/tErlServer.erl @@ -69,13 +69,18 @@ effectful_serve(This) -> %% listen case gen_tcp:listen(Port, Options) of {ok, ListenSocket} -> + ?INFO(server_listening, {Port}), This1 = oop:set(This, listenSocket, ListenSocket), %% spawn acceptor {_Acceptor, This2} = effectful_new_acceptor(This1), - {ok, This2} + {ok, This2}; + + {error, eaddrinuse} -> + error_logger:format("couldn't bind port ~p, address in use", [Port]), + {{error, eaddrinuse}, This} %% state before the accept end. effectful_new_acceptor(This) -> @@ -96,7 +101,7 @@ effectful_new_acceptor(This) -> {Acceptor, This1}. -catches(This, Pid, acceptor_done) -> +catches(_This, _Pid, normal) -> ok. %% %% The current acceptor has died, wait a little and try again %% diff --git a/lib/erl/lib/thrift/src/server/tSimpleServer.erl b/lib/erl/lib/thrift/src/server/tSimpleServer.erl index 5b457cdd..6dcc7236 100644 --- a/lib/erl/lib/thrift/src/server/tSimpleServer.erl +++ b/lib/erl/lib/thrift/src/server/tSimpleServer.erl @@ -4,6 +4,9 @@ %%% See accompanying file LICENSE or visit the Thrift site at: %%% http://developers.facebook.com/thrift/ +%%% NOTE: tSimpleServer's design isn't compatible with our concurrency model. +%%% It won't work in principle, and certainly not in practice. YMMV. + -module(tSimpleServer). -include("oop.hrl"). @@ -46,6 +49,7 @@ inspect(_This) -> new(Handler, Processor, ServerTransport, TransportFactory, ProtocolFactory) -> Super = (super()):new(Handler, Processor, ServerTransport, TransportFactory, ProtocolFactory), + error_logger:warning_msg("tSimpleServer has an incompatable design and doesn't work. Promise."), #?MODULE{super=Super}. new(Handler, Processor, ServerTransport) -> @@ -57,13 +61,14 @@ new(Handler, Processor, ServerTransport, TransportFactory) -> % serve(This) -> + exit(tSimpleServer_doesnt_work), ST = oop:get(This, serverTransport), ?R0(ST, effectful_listen), serve_loop(This). serve_loop(This) -> - io:format("~nready.~n", []), + error_logger:info_msg("ready.", []), ST = oop:get(This, serverTransport), Client = ?RT0(ST, accept, infinity), @@ -74,7 +79,7 @@ serve_loop(This) -> PF = oop:get(This, protocolFactory), Prot = ?F1(PF, getProtocol, Trans), %% cpiro: OPAQUE!! Prot = start_new(tBinaryProtocol, [Trans]) - io:format("client accept()ed~n", []), + error_logger:info_msg("client accept()ed", []), serve_loop_loop(This, Prot), % giggle loop? @@ -88,16 +93,16 @@ serve_loop_loop(This, Prot) -> Handler = oop:get(This, handler), Processor = oop:get(This, processor), Val = apply(Processor, process, [Handler, Prot, Prot]), %% TODO(cpiro): make processor a gen_server instance - io:format("request processed: rv=~p~n", [Val]), + error_logger:info_msg("request processed: rv=~p", [Val]), loop catch %% TODO(cpiro) case when is_record(...) to pick out our exception %% records vs. normal erlang throws E when is_record(E, tTransportException) -> - io:format("tTransportException (normal-ish?)~n", []), + error_logger:info_msg("tTransportException (normal-ish?)", []), close; F -> - io:format("EXCEPTION: ~p~n", [F]), + error_logger:info_msg("EXCEPTION: ~p", [F]), close end, case Next of diff --git a/lib/erl/lib/thrift/src/tErlProcessor.erl b/lib/erl/lib/thrift/src/tErlProcessor.erl index a95ef536..ec263e36 100644 --- a/lib/erl/lib/thrift/src/tErlProcessor.erl +++ b/lib/erl/lib/thrift/src/tErlProcessor.erl @@ -6,6 +6,7 @@ -module(tErlProcessor). +-include("thrift.hrl"). -include("oop.hrl"). -include("tErlProcessor.hrl"). @@ -58,5 +59,5 @@ new(GP, Handler) -> process(This, Iprot, Oprot) -> GP = oop:get(This, generatedProcessor), Handler = oop:get(This, handler), - + apply(GP, process, [Handler, Iprot, Oprot]). diff --git a/lib/erl/lib/thrift/src/thrift.erl b/lib/erl/lib/thrift/src/thrift.erl new file mode 100644 index 00000000..feabb1d1 --- /dev/null +++ b/lib/erl/lib/thrift/src/thrift.erl @@ -0,0 +1,25 @@ +%%% Copyright (c) 2007- Facebook +%%% Distributed under the Thrift Software License +%%% +%%% See accompanying file LICENSE or visit the Thrift site at: +%%% http://developers.facebook.com/thrift/ + +-module(thrift). + +-export([start/2, shutdown/0, stop/1]). +-behaviour(application). + +-include("thrift.hrl"). + +%%% +%%% behavior definition +%%% + +start(Type, StartArgs) -> + ok. + +shutdown() -> + application:stop(?MODULE). + +stop(_State) -> + ok. diff --git a/lib/erl/lib/thrift/src/thrift_logger.erl b/lib/erl/lib/thrift/src/thrift_logger.erl new file mode 100644 index 00000000..286d40d1 --- /dev/null +++ b/lib/erl/lib/thrift/src/thrift_logger.erl @@ -0,0 +1,282 @@ +%%% Copyright (c) 2007- Facebook +%%% Distributed under the Thrift Software License +%%% +%%% See accompanying file LICENSE or visit the Thrift site at: +%%% http://developers.facebook.com/thrift/ + +-module(thrift_logger). + +-behaviour(gen_event). + +-include("thrift_logger.hrl"). + +%% gen_event callbacks +-export([init/1, handle_event/2, handle_call/2, + handle_info/2, terminate/2, code_change/3]). + +-export([install/0, install/1]). + +%% ensure the regular logger is out and ours is in +install() -> + install([]). +install(Args) -> + %% remove loggers + lists:foreach(fun(Logger) -> + case Logger of + _ -> gen_event:delete_handler(error_logger, Logger, normal) + end end, + gen_event:which_handlers(error_logger)), + + %% TODO(cpiro): sasl someday? + %% gen_event:add_handler(error_logger, sasl_report_file_h, {LogFile, all}), + gen_event:add_handler(error_logger, ?MODULE, Args). + +%% how to output +format(Format, Data) -> + io:format(Format, Data). + +%% convenience +sformat(Format, Data) -> + thrift_utils:sformat(Format, Data). + +%%==================================================================== +%% gen_event callbacks +%%==================================================================== +%%-------------------------------------------------------------------- +%% @spec init(Args) -> {ok, State}. +%% +%% @doc +%% Whenever a new event handler is added to an event manager, +%% this function is called to initialize the event handler. +%% @end +%%-------------------------------------------------------------------- +init([]) -> + {ok, #thrift_logger_state{ + term_width = 110, + force_one_line = true, + omit = [oop_new], % req_processed + gen_server_messages = false, + lookup = true + }}; + +init([State]) -> + {ok, State}. + +%%-------------------------------------------------------------------- +%% @spec handle_event(Event, State) -> {ok, State} | +%% {swap_handler, Args1, State1, Mod2, Args2} | +%% remove_handler. +%% +%% @doc +%% Whenever an event manager receives an event sent using +%% gen_event:notify/2 or gen_event:sync_notify/2, this function is called for +%% each installed event handler to handle the event. +%% @end +%%-------------------------------------------------------------------- +handle_event2(Symbol, Pid, Type, Message, State) -> % Message must be a string + {ok, MessageSafe, NL} = regexp:gsub(Message, "[\n]+", " "), % collapse whitespace to one space + + Type1 = + case Type of + "" -> ""; + _ -> sformat("~p ", [Type]) + end, + + Banner = sformat("~s ~p ~s", [Symbol, Pid, Type1]), + BannerLen = length(Banner), + {Output, OutputSafe} = + try %% there's no way to see if Message is a string? just try + {sformat("~s", [Message]), + sformat("~s", [MessageSafe])} + catch X -> why_doesnt_this_work + end, + + Length = + case (length(OutputSafe) + BannerLen) < State#thrift_logger_state.term_width of + true -> short; + false -> long + end, + + OneLine = + case NL == 0 of + true -> oneliner; + false -> multiline + end, + + case { State#thrift_logger_state.force_one_line, Length, OneLine } of + %% one line and short ... print as is + {_, short, oneliner} -> + format("~s~s~n", [Banner, OutputSafe]); + + %% too long ... squash to one + {true, long, _} -> + O = Banner ++ OutputSafe, + Format = sformat("~~~ps >~n", [State#thrift_logger_state.term_width-2]), % e.g. "~80s >~n" + format(Format, [O]); + + %% short but multiline... collapse to one + {true, short, multiline} -> + format("~s~s~n", [Banner, OutputSafe]); + + %% just print it + _ -> + format("~s~n~s~n~n", [Banner, Output]) + end. + +%% +handle_event1({What, _Gleader, {Pid, Format, Data}}, State) when is_list(Format) -> + Symbol = case What of + error -> "!!"; + warning_msg -> "**"; + info_msg -> ".."; + _Else -> "??" + end, + + case Format of + "** Generic server ~p terminating \n** Last message in was ~p~n** When Server state == ~p~n** Reason for termination == ~n** ~p~n" -> + %% v- Pid is a pattern match, not a bind + [Pid, LastMessage, Obj, Reason] = Data, + + %% TODO: move as much logic as possible out of thrift_logger + Ignore = error /= thrift_utils:unnest_record(Reason, tTransportException), + + case Ignore of + true -> + ok; + false -> + Format1 = "** gen_server terminating in message ~p~n** State = ~s~n** Reason = ~s~n", + Message = sformat(Format1, [LastMessage, oop:inspect(Obj), oop:inspect(Reason)]), %% TODO(cpiro): hope Reason is an object? + handle_event2(Symbol, Pid, "", Message, State) + end; + _ -> + Message = sformat(Format, Data), + handle_event2(Symbol, Pid, "", Message, State) + end, + {ok, State}; + +handle_event1({What, _Gleader, {Pid, Type, Report}}, State) -> + Symbol = case What of + error_report -> "!!"; + warning_report -> "**"; + info_report -> ".."; + _Else -> "??" + end, + + case Type of + {thrift_info, TI} -> + %% should we show it? + case not lists:member(TI, State#thrift_logger_state.omit) of + true -> + Message = handle_thrift_info(TI, Report, State), + handle_event2(Symbol, Pid, "", Message, State); + false -> + ok + end; + crash_report -> + %% [Cruft|_] = Report, %% + %% {value, {_, Reason}} = lists:keysearch(error_info, 1, Cruft), %% + %% {value, {_, {_, _, [_,_,_,_, Obj, []]}}} = lists:keysearch(initial_call, 1, Cruft), %% + %% sformat("state == ~s~nreason ==~s", [oop:inspect(Obj), oop:inspect(Reason)]), %% + ok; + progress -> + ok; + + _ -> + Message = sformat("|| ~s", [oop:inspect(Report)]), + handle_event2(Symbol, Pid, Type, Message, State) + end, + {ok, State}; + +handle_event1(_Event, State) -> + handle_event2("??", "", "", _Event, State), + {ok, State}. + +handle_event(Event, State) -> + try + handle_event1(Event, State) + catch + _:E -> + format("~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~n error logger error:~n ~p~n Event = ~p~n State = ~p~n ~p~n~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~n", + [E, Event, State, erlang:get_stacktrace()]), + {ok, State} + end. + +%% thrift info handlers +handle_thrift_info(oop_new, {Args, Class, Object}, State) -> + %% arg Class can't come first! Then it'd look like a Class object + L = io_lib:format("~p:new(~s) = ~s", [Class, thrift_utils:unbrack(Args), oop:inspect(Object)]), + lists:flatten(L); + +handle_thrift_info(server_listening, {Port}, State) -> + sformat("server listening on port ~p", [Port]); + +handle_thrift_info(req_processed, {Value}, State) -> + sformat("request: ~p", [Value]); + +handle_thrift_info(conn_accepted, {AddrString}, State) -> + sformat("connection accepted from ~s", [AddrString]); + +handle_thrift_info(conn_closed, {AddrString}, State) -> + sformat("connection closed from ~s", [AddrString]); + +handle_thrift_info(Else, Report, State) -> + sformat("~p ~s", [Else, oop:inspect(Report)]). + +%%-------------------------------------------------------------------- +%% @spec handle_call(Request, State) -> {ok, Reply, State} | +%% {swap_handler, Reply, Args1, State1, +%% Mod2, Args2} | +%% {remove_handler, Reply}. +%% +%% @doc +%% Whenever an event manager receives a request sent using +%% gen_event:call/3,4, this function is called for the specified event +%% handler to handle the request. +%% @end +%%-------------------------------------------------------------------- +handle_call(_Request, State) -> + Reply = ok, + {ok, Reply, State}. + +%%-------------------------------------------------------------------- +%% @spec handle_info(Info, State) -> {ok, State} | +%% {swap_handler, Args1, State1, Mod2, Args2} | +%% remove_handler. +%% +%% @doc +%% This function is called for each installed event handler when +%% an event manager receives any other message than an event or a synchronous +%% request (or a system message). +%% @end +%%-------------------------------------------------------------------- +handle_info(_Info, State) -> + {ok, State}. + +%%-------------------------------------------------------------------- +%% @spec terminate(Reason, State) -> void(). +%% +%% @doc +%% Whenever an event handler is deleted from an event manager, +%% this function is called. It should be the opposite of Module:init/1 and +%% do any necessary cleaning up. +%% @end +%%-------------------------------------------------------------------- +terminate(normal, _State) -> + ok; +terminate(Reason, _State) -> + format("*****************~n~n frick, error logger terminating: ~p~n~n*****************~n~n", [Reason]), + ok. + +%%-------------------------------------------------------------------- +%% @spec code_change(OldVsn, State, Extra) -> {ok, NewState}. +%% +%% @doc +%% Convert process state when code is changed +%% @end +%%-------------------------------------------------------------------- +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%==================================================================== +%%% Internal functions +%%==================================================================== diff --git a/lib/erl/lib/thrift/src/thrift_oop_server.erl b/lib/erl/lib/thrift/src/thrift_oop_server.erl index 8fc91238..c21c434d 100644 --- a/lib/erl/lib/thrift/src/thrift_oop_server.erl +++ b/lib/erl/lib/thrift/src/thrift_oop_server.erl @@ -72,21 +72,16 @@ stop() -> %% {stop, Reason} %%-------------------------------------------------------------------- -unparenth(Args) -> - Args. - init({Class, Args}) -> process_flag(trap_exit, true), - if - true -> % lists:member(Class, Class:interface(subclasses)) -> - io:format("oop_server init: ~p := ~p:new(~p)~n", [self(), Class, unparenth(Args)]), - State = apply(Class, new, Args), % TODO(cpiro): try catch? - io:format(" =>~p~n", [oop:inspect(State)]), - {ok, State} - - %% true -> %% - %% {stop, invalid_subclass} %% + try + State = apply(Class, new, Args), + ?INFO(oop_new, {Args, Class, State}), + {ok, State} + catch + E -> {stop, {new_failed, E}} end; + init(_) -> {stop, invalid_params}. @@ -126,8 +121,8 @@ handle_cast({Method, Args}, State) -> ). handle_either(Type, Request, From, State) -> - %% io:format("~p: ~p~n", [?SERVER, oop:inspect(State)]), - %% io:format(" handle_call(Request=~p, From=~p, State)~n", [Request, From]), + %% error_logger:info_msg("~p: ~p", [?SERVER, oop:inspect(State)]), + %% error_logger:info_msg("handle_call(Request=~p, From=~p, State)", [Request, From]), case Request of {get, [Field]} -> @@ -138,11 +133,14 @@ handle_either(Type, Request, From, State) -> State1 = oop:set(State, Field, Value), ?REPLY(Value, State1); + {class, []} -> + ?REPLY(?CLASS(State), State); + {Method, Args} -> handle_method(Type, State, Method, Args); _ -> - io:format(" ERROR: Request = ~p nomatch {Method, Args}~n", [Request]), + error_logger:format("no match for Request = ~p", [Request]), %% {stop, server_error, State} {reply, server_error, State} end. @@ -160,8 +158,8 @@ handle_method(Type, State, Method, Args) -> {true, _MalformedReturn} -> %% TODO(cpiro): bad match -- remove when we're done converting - io:format(" ERROR: oop:call(effectful_*,..,..) malformed return value ~p~n", - [_MalformedReturn]), + error_logger:format("oop:call(effectful_*,..,..) malformed return value ~p", + [_MalformedReturn]), %% {stop, server_error, State} {noreply, State}; @@ -177,18 +175,23 @@ handle_method(Type, State, Method, Args) -> %% {stop, Reason, State} (terminate/2 is called) %%-------------------------------------------------------------------- handle_info({'EXIT', Pid, Except} = All, State) -> - case catch oop:call(State, catches, [Pid, Except]) of - {'EXIT', MM} when element(1,MM) == missing_method -> - io:format("UNHANDLED ~p by ~p!~n", [All, self()]), - %% not caught + Result = try + oop:call(State, catches, [Pid, Except]) + catch + exit:{missing_method, _} -> + unhandled + end, + + case Result of + unhandled -> + error_logger:format("unhandled exit ~p", [All]), {stop, All, State}; - _IsCaught -> - %% caught and handled + _WasHandled -> {noreply, State} end; - + handle_info(Info, State) -> - io:format("~p infoED!: ~p~n", [self(), Info]), + error_logger:info_msg("~p", [Info]), {noreply, State}. %%-------------------------------------------------------------------- @@ -197,7 +200,7 @@ handle_info(Info, State) -> %% Returns: any (ignored by gen_server) %%-------------------------------------------------------------------- terminate(Reason, State) -> - io:format("~p terminated!: ~p~n", [self(), Reason]), + %%error_logger:format("~p terminated!: ~p", [self(), Reason]), ok. %%-------------------------------------------------------------------- diff --git a/lib/erl/lib/thrift/src/thrift_utils.erl b/lib/erl/lib/thrift/src/thrift_utils.erl index c1c6a259..f78767c8 100644 --- a/lib/erl/lib/thrift/src/thrift_utils.erl +++ b/lib/erl/lib/thrift/src/thrift_utils.erl @@ -1,11 +1,52 @@ +%%% Copyright (c) 2007- Facebook +%%% Distributed under the Thrift Software License +%%% +%%% See accompanying file LICENSE or visit the Thrift site at: +%%% http://developers.facebook.com/thrift/ + -module(thrift_utils). --export([tabulate/2,dict_size/1]). +-include("transport/tTransportException.hrl"). + +-export([tabulate/2, dict_size/1, sformat/2, unbrack/1, first_item/1, unnest_record/2]). -tabulateh(N,M,_) when N==M -> []; -tabulateh(N,M,F) -> [F(N)|tabulateh(N+1,M,F)]. -tabulate(N,F) -> tabulateh(0,N,F). +%% tabulate +tabulate(N,F) -> + tabulate(0, N, F). -% makin me sad +tabulate(N,M,_) when N==M -> + []; +tabulate(N,M,F) -> + [F(N) | tabulate(N+1, M, F)]. + +%% makin me sad dict_size(Dict) -> dict:fold(fun (_,_,I) -> I+1 end,0,Dict). + +%% I CAN HAS EAZIER KTHX +sformat(Format, Data) when is_list(Data) -> + lists:flatten(io_lib:format(Format, Data)); +sformat(Format, Item) -> + error_logger:warning_msg("sformat called with non-list Data: (~p, ~p)", [Format, Item]), + sformat(Format, [Item]). + +%% render a list and pick off the square brackets +unbrack(List) -> + List1 = sformat("~w", [List]), + string:substr(List1, 2, length(List1)-2). + +first_item(DeepTuple) -> + case is_tuple(DeepTuple) of + true -> first_item(element(1, DeepTuple)); + false -> DeepTuple + end. + +unnest_record(Term, RecordTag) -> + case is_record(Term, RecordTag) of + true -> + {ok, Term}; + false when is_tuple(Term) -> + unnest_record(element(1, Term), RecordTag); + _ -> + error + end. diff --git a/lib/erl/lib/thrift/src/transport/tErlAcceptor.erl b/lib/erl/lib/thrift/src/transport/tErlAcceptor.erl index fd062601..3407c82c 100644 --- a/lib/erl/lib/thrift/src/transport/tErlAcceptor.erl +++ b/lib/erl/lib/thrift/src/transport/tErlAcceptor.erl @@ -12,6 +12,8 @@ -include("transport/tServerSocket.hrl"). -include("transport/tErlAcceptor.hrl"). +-include_lib("kernel/include/inet.hrl"). + -behavior(oop). -export([attr/4, super/0, inspect/1]). @@ -62,15 +64,15 @@ new(ServerPid, TF, PF) -> %%% accept(This, ListenSocket, GP, Handler) -> - io:format("acceptor started~n",[]), - ServerPid = oop:get(This, serverPid), - + case catch gen_tcp:accept(ListenSocket) of {ok, Socket} -> - ?C0(ServerPid, effectful_new_acceptor), %% cast to create new acceptor + AddrString = render_addr(Socket), + ?INFO(conn_accepted, {AddrString}), + %% start_new(tSocket, []) Client = oop:start_new(tSocket, []), ?R1(Client, effectful_setHandle, Socket), %% TODO(cpiro): should we just let this be a param to the constructor? @@ -88,139 +90,51 @@ accept(This, ListenSocket, GP, Handler) -> receive_loop(This, Processor, Prot, Prot), - exit(acceptor_done); %% TODO(cpiro): grace? + ?INFO(conn_closed, {AddrString}), + + exit(normal); Else -> - R = lists:flatten( - io_lib:format("accept() failed: ~p", [Else])), - + R = thrift_utils:sformat("accept() failed: ~p", [Else]), exit(tTransportException:new(R)) end. receive_loop(This, Processor, Iprot, Oprot) -> - case catch ?R2(Processor, process, Iprot, Oprot) of - {'EXIT', X} -> - io:format("Acceptor: we gotta ~p~n", [X]); - - Value -> - io:format("request processed: rv=~p~n", [Value]), - receive_loop(This, Processor, Iprot, Oprot) + try + Value = ?R2(Processor, process, Iprot, Oprot), + ?INFO(req_processed, {Value}), + receive_loop(This, Processor, Iprot, Oprot) + catch + %% the following clause must be last because we might reexit + %% cpiro: breaks if it's a subclass of tTransportException + %% since unnest_record knows nothing about oop + exit:Else -> + case thrift_utils:unnest_record(Else, tTransportException) of + {ok, TTE} when TTE#tTransportException.type == ?tTransportException_NOT_OPEN -> + ok; %% will exit to tErlAcceptor + _ -> + exit(Else) %% shouldn't have caught it in the first place + end end. -%%% -%%% error handlers -%%% - -%% end - -%%% old codez - -%% effectful_listen(This) -> %% -%% Port = oop:get(This, port), %% -%% Options = [binary, {packet, 0}, {active, false}], % was [] %% -%% %% -%% case gen_tcp:listen(Port, Options) of %% -%% {ok, ListenSocket} -> %% -%% This1 = oop:set(This, handle, ListenSocket), %% -%% {ok, This1} %% -%% %% -%% % {error, _} -> %% -%% % TODO: no error handling in Ruby version? %% -%% end. %% -%% %% -%% accept(This) -> %% -%% case oop:get(This, handle) of %% -%% nil -> %% -%% nil; % cpiro: sic the Ruby code %% -%% %% -%% Handle -> %% -%% case gen_tcp:accept(Handle) of %% -%% {ok, Sock} -> %% -%% Trans = oop:start_new(tSocket, []), %% -%% ?R1(Trans, effectful_setHandle, Sock), %% -%% Trans %% -%% % {error, _} -> %% -%% % TODO: no error handling in Ruby version? %% -%% end %% -%% end. %% -%% %% -%% effectful_close(This) -> %% -%% case oop:get(This, handle) of %% -%% nil -> %% -%% {nil, This}; %% -%% Handle -> %% -%% case gen_tcp:close(Handle) of %% -%% ok -> %% -%% {ok, This} % cpiro: sic the Ruby version: don't set handle to nil %% -%% % {error, _} -> %% -%% % TODO: no error handling in Ruby version? %% -%% end %% -%% end. %% - - -%%% teh iservez - -%% -module(iserve_socket). %% -%% %% -%% -export([start_link/3]). %% -%% %% -%% -export([init/1]). %% -%% -include("iserve.hrl"). %% -%% %% -%% %TEST %% -%% -export([handle_get/2]). %% -%% %% -%% -define(not_implemented_501, "HTTP/1.1 501 Not Implemented\r\n\r\n"). %% -%% -define(forbidden_403, "HTTP/1.1 403 Forbidden\r\n\r\n"). %% -%% -define(not_found_404, "HTTP/1.1 404 Not Found\r\n\r\n"). %% -%% %% -%% -record(c, {sock, %% -%% port, %% -%% peer_addr, %% -%% peer_port %% -%% }). %% -%% %% -%% -define(server_idle_timeout, 30*1000). %% -%% %% -%% start_link(ListenPid, ListenSocket, ListenPort) -> %% -%% proc_lib:spawn_link(?MODULE, init, [{ListenPid, ListenSocket, ListenPort}]). %% -%% %% - - -%% init({Listen_pid, Listen_socket, ListenPort}) -> %% -%% % error_logger:info_msg("Socket Started~n"), %% -%% case catch gen_tcp:accept(Listen_socket) of %% -%% {ok, Socket} -> %% -%% %% Send the cast message to the listener process to create a new acceptor %% -%% iserve_server:create(Listen_pid, self()), %% -%% {ok, {Addr, Port}} = inet:peername(Socket), %% -%% Conn = #c{sock = Socket, %% -%% port = ListenPort, %% -%% peer_addr = Addr, %% -%% peer_port = Port}, %% -%% request(Conn, #req{}); %% Jump to state 'request' %% -%% Else -> %% -%% error_logger:error_report([{application, iserve}, %% -%% "Accept failed error", %% -%% io_lib:format("~p",[Else])]), %% -%% exit({error, accept_failed}) %% -%% end. %% -%% %% - -%% request(Conn, Req) -> %% -%% case gen_tcp:recv(Conn#c.sock, 0, ?server_idle_timeout) of %% -%% {ok, {http_request,Method,Path,Version}} -> %% -%% headers(Conn, Req#req{vsn = Version, %% -%% method = Method, %% -%% uri = Path}, []); %% -%% {error, {http_error, "\r\n"}} -> %% -%% request(Conn, Req); %% -%% {error, {http_error, "\n"}} -> %% -%% request(Conn, Req); %% -%% {tcp_closed, _Port} -> %% -%% error_logger:info_msg("Closed connection: ~p ~p~n", [Conn#c.peer_addr, Conn#c.peer_port]), %% -%% exit(normal); %% -%% _Other -> %% -%% exit(normal) %% -%% end. %% - +%% helper functions + +%% @param Socket the socket in question +%% TODO(cpiro): there probably needs to be a switch for DoLookup somewhere prominent and outside the lib, +%% probably at the "application" level +render_addr(Socket) -> + DoLookup = true, + {ok, {Peer, Port}} = inet:peername(Socket), + + case Peer of + _ when DoLookup -> + case catch inet:gethostbyaddr(Peer) of + {ok, Hostent} -> + thrift_utils:sformat("~s:~p", [Hostent#hostent.h_name, Port]); + _ -> + "??" + end; + + {A,B,C,D} when not DoLookup -> + thrift_utils:sformat("~p.~p.~p.~p:~p", [A,B,C,D,Port]) + end. diff --git a/lib/erl/lib/thrift/src/transport/tSocket.erl b/lib/erl/lib/thrift/src/transport/tSocket.erl index 3ac066c6..dd1ff9b0 100644 --- a/lib/erl/lib/thrift/src/transport/tSocket.erl +++ b/lib/erl/lib/thrift/src/transport/tSocket.erl @@ -15,7 +15,7 @@ -behavior(oop). --export([attr/4, super/0, inspect/1]). +-export([attr/4, super/0, inspect/1, catches/2]). -export([new/0, new/1, new/2, effectful_setHandle/2, effectful_open/1, @@ -91,7 +91,7 @@ write(This, Str) -> Handle = oop:get(This, handle), Val = gen_tcp:send(Handle, Str), - %% io:format("WRITE |~p|(~p)~n", [Str,Val]), + %% error_logger:info_msg("WRITE |~p| (~p)", [Str,Val]), case Val of {error, _} -> @@ -110,8 +110,6 @@ read(This, Sz) -> {ok, Data} -> Data; {error, Error} -> - io:format("in tSocket:read/2: gen_tcp:recv(~p, ~p) => {error, ~p}~n", - [Handle, Sz, Error]), exit(tTransportException:new(?tTransportException_NOT_OPEN, "in tSocket:read/2: gen_tcp:recv")) end. @@ -123,4 +121,3 @@ effectful_close(This) -> gen_tcp:close(Handle), {ok, oop:set(This, handle, nil)} end. - diff --git a/lib/erl/lib/thrift/src/transport/tTransport.erl b/lib/erl/lib/thrift/src/transport/tTransport.erl index c15a632d..6ec115a6 100644 --- a/lib/erl/lib/thrift/src/transport/tTransport.erl +++ b/lib/erl/lib/thrift/src/transport/tTransport.erl @@ -70,7 +70,7 @@ readAll_loop(This, Sz, Buff, Have) -> %% possibly discarding less than Length bytes of data when %% the socket gets closed from the other side. - %% io:format("READ |~p|~n", [Chunk]), + %% error_logger:info_msg("READ |~p|", [Chunk]), Have1 = Have + (Sz-Have), % length(Chunk) Buff1 = Buff ++ Chunk, % TODO: ++ efficiency? diff --git a/tutorial/erl/server.erl b/tutorial/erl/server.erl index 0d5c1a91..2a44e1d0 100644 --- a/tutorial/erl/server.erl +++ b/tutorial/erl/server.erl @@ -1,6 +1,7 @@ -module(server). -include("thrift.hrl"). +-include("thrift_logger.hrl"). -include("transport/tSocket.hrl"). -include("protocol/tBinaryProtocol.hrl"). @@ -9,20 +10,22 @@ -include("calculator.hrl"). - -export([start/0, start/1, stop/1, ping/0, add/2, calculate/2, getStruct/1, zip/0]). +debug(Format, Data) -> + error_logger:info_msg(Format, Data). + ping() -> - io:format("ping()~n",[]), - nil. + debug("ping()",[]), + ok. add(N1, N2) -> - io:format("add(~p,~p)~n",[N1,N2]), + debug("add(~p,~p)",[N1,N2]), N1+N2. calculate(Logid, Work) -> { Op, Num1, Num2 } = { Work#work.op, Work#work.num1, Work#work.num2 }, - io:format("calculate(~p, {~p,~p,~p})~n", [Logid, Op, Num1, Num2]), + debug("calculate(~p, {~p,~p,~p})", [Logid, Op, Num1, Num2]), case Op of ?tutorial_ADD -> Num1 + Num2; ?tutorial_SUBTRACT -> Num1 - Num2; @@ -39,11 +42,12 @@ calculate(Logid, Work) -> end. getStruct(Key) -> - io:format("getStruct(~p)~n", [Key]), + debug("getStruct(~p)", [Key]), #sharedStruct{key=Key, value="RARG"}. zip() -> - io:format("zip~n"). + debug("zip", []), + ok. %% @@ -51,6 +55,12 @@ start() -> start(9090). start(Port) -> + thrift_logger:install([#thrift_logger_state{ + force_one_line = false, %% should we collapse all errors to one line? + term_width = 110, %% if so, crop output at this width + omit = [oop_new, req_processed] %% don't show these kinds of infos + }]), + Handler = ?MODULE, Processor = calculator, @@ -62,9 +72,10 @@ start(Port) -> Server = oop:start_new(ServerFlavor, [Port, Handler, Processor, ServerTransport, TF, PF]), - ?R0(Server, effectful_serve), - - Server. + case ?R0(Server, effectful_serve) of + ok -> Server; + Error -> Error + end. stop(Server) -> ?C0(Server, stop), -- 2.17.1