[thrift] clean up error logging in Erlang

Summary: pushed all formatting out of thrift_error_logger.erl, reenable crash logs, standardize

Reviewed By: eletuchy

Test Plan: works with latest ch server

git-svn-id: https://svn.apache.org/repos/asf/incubator/thrift/trunk@665305 13f79535-47bb-0310-9956-ffa450edef68

diff --git a/lib/erl/include/thrift.hrl b/lib/erl/include/thrift.hrl
index fdeaf1d..efd2b43 100644 (file)
--- a/lib/erl/include/thrift.hrl
+++ b/lib/erl/include/thrift.hrl
@@ -9,8 +9,8 @@
 -define(ERROR(F, D),
        error_logger:format(F, D)).
 
--define(INFO(Type, Report),
-       error_logger:info_report({thrift_info, Type}, Report)).
+-define(INFO(F, D),
+       error_logger:info_msg(F, D)).
 
 -include("thrift_macros.hrl").
 -include("thrift_constants.hrl").

diff --git a/lib/erl/src/server/tErlServer.erl b/lib/erl/src/server/tErlServer.erl
index 0e61e38..4e1f6fc 100644 (file)
--- a/lib/erl/src/server/tErlServer.erl
+++ b/lib/erl/src/server/tErlServer.erl
@@ -69,7 +69,7 @@ effectful_serve(This) ->
     %% listen
     case gen_tcp:listen(Port, Options) of 
        {ok, ListenSocket} ->
-           ?INFO(server_listening, {Port}),
+           ?INFO("thrift server listening on port ~p", [Port]),
 
            This1 = oop:set(This, listenSocket, ListenSocket),
 
@@ -79,7 +79,7 @@ effectful_serve(This) ->
            {ok, This2};
 
        {error, eaddrinuse} ->
-           error_logger:format("couldn't bind port ~p, address in use", [Port]),
+           ?ERROR("thrift couldn't bind port ~p, address in use", [Port]),
            {{error, eaddrinuse}, This} %% state before the accept
     end.
 
@@ -111,7 +111,7 @@ catches(_This, _Pid, normal) ->
 %%     {noreply,State};                                                                                                       %%
 
 %% terminate(Reason, State) ->                                                                                        %%
-%%     error_logger:info_msg( "Terminating error: ~p~n", [Reason]), % added                                           %%
+%%     ?INFO( "Terminating error: ~p~n", [Reason]), % added                                                           %%
 %%     gen_tcp:close(State#state.listen_socket),                                                                      %%
 %%     ok.                                                                                                            %%
 %%                                                                                                                    %%

diff --git a/lib/erl/src/thrift_logger.erl b/lib/erl/src/thrift_logger.erl
index dee014b..8528da3 100644 (file)
--- a/lib/erl/src/thrift_logger.erl
+++ b/lib/erl/src/thrift_logger.erl
@@ -71,6 +71,8 @@ init([]) ->
       {term_width, 80},
       {force_one_line, false},
       {omit, []},
+      {omit_fmt, []},
+      {show_pid, false},
       {gen_server_messages, true},
       {lookup, false}
     ], %% configuration before we try loading from file
@@ -98,14 +100,18 @@ handle_event2(Symbol, Pid, Type, Message, State) -> % Message must be a string
            _  -> 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,
+    Banner =
+        case ?CONFIG(show_pid) of
+            true ->
+                sformat("~s ~s ~s", [Symbol, Pid, Type1]);
+            false ->
+                sformat("~s~i ~s", [Symbol, Pid, Type1])
+        end,
+    BannerLen = length(Banner),
+
+    %% there's no way to see if Message is a string? just try
+    Output = sformat("~s", [Message]),
+    OutputSafe = sformat("~s", [MessageSafe]),
 
     Length =
        case (length(OutputSafe) + BannerLen) < ?CONFIG(term_width) of
@@ -179,9 +185,14 @@ handle_event1({What, _Gleader, {Ref, Format, Data}}, State) when is_list(Format)
        {?GS_TERM_FORMAT, _Dta} ->
            Message = sformat("DATA DIDN'T MATCH: ~p~n", [Data]) ++ sformat(Format, Data),
            handle_event2(Symbol, Ref, "", Message, State);
-       {_Fmt, _Dta} ->
-           Message = sformat(Format, Data),
-           handle_event2(Symbol, Ref, "", Message, State)
+       {_, _} ->
+           case lists:member(Format, ?CONFIG(omit_fmt)) of
+               false ->
+                   Message = sformat(Format, Data),
+                   handle_event2(Symbol, Ref, "", Message, State);
+               true ->
+                   ok
+           end
     end,
     {ok, State};
 
@@ -194,22 +205,20 @@ handle_event1({What, _Gleader, {Pid, Type, Report}}, State) ->
     end,
 
     case Type of
-       {thrift_info, TI} ->
-           %% should we show it?
-           case not lists:member(TI, ?CONFIG(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 ->
+        crash_report ->
+            case do_print_crash_report(Report) of
+                true ->
+                    io:format("~~~~ crash report: '~p'~n", [Report]);
+                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;
 
        _ ->
@@ -232,30 +241,6 @@ handle_event(Event, State) ->
            {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_timeout, {AddrString}, State) ->
-    sformat("connection timed out 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,
@@ -348,3 +333,16 @@ config(Item, State) ->
        Else ->
            ?ERROR("config for ~p is unavailable: ~p", [Item, Else])
     end.
+
+do_print_crash_report(Report) ->
+    case Report of
+        [[_,_,{error_info, XXX}|_] | _]  ->
+            case thrift_utils:first_item(XXX) of
+                tTransportException ->
+                    false;
+                _ ->
+                    true
+            end;
+        _ ->
+            true
+    end.

diff --git a/lib/erl/src/thrift_oop_server.erl b/lib/erl/src/thrift_oop_server.erl
index c21c434..57c4772 100644 (file)
--- a/lib/erl/src/thrift_oop_server.erl
+++ b/lib/erl/src/thrift_oop_server.erl
@@ -76,7 +76,7 @@ init({Class, Args}) ->
     process_flag(trap_exit, true),
     try
        State = apply(Class, new, Args),
-       ?INFO(oop_new, {Args, Class, State}),
+       ?INFO("thrift ~p:new(~s) = ~s", [Class, thrift_utils:unbrack(Args), oop:inspect(State)]),
        {ok, State}
     catch
        E -> {stop, {new_failed, E}}

diff --git a/lib/erl/src/thrift_utils.erl b/lib/erl/src/thrift_utils.erl
index f78767c..8305224 100644 (file)
--- a/lib/erl/src/thrift_utils.erl
+++ b/lib/erl/src/thrift_utils.erl
@@ -35,18 +35,17 @@ 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.
+first_item(DeepTuple) when is_tuple(DeepTuple) ->
+    first_item(element(1, DeepTuple));
+first_item(NotTuple) ->
+    NotTuple.
 
 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
+        true ->
+            {ok, Term};
+        false when is_tuple(Term) ->
+            unnest_record(element(1, Term), RecordTag);
+        _ ->
+            error
     end.

diff --git a/lib/erl/src/transport/tErlAcceptor.erl b/lib/erl/src/transport/tErlAcceptor.erl
index f3308cf..7586f60 100644 (file)
--- a/lib/erl/src/transport/tErlAcceptor.erl
+++ b/lib/erl/src/transport/tErlAcceptor.erl
@@ -72,7 +72,7 @@ accept(This, ListenSocket, GP, Handler) ->
            ?C0(ServerPid, effectful_new_acceptor), %% cast to create new acceptor
 
            AddrString = render_addr(Socket),
-           ?INFO(conn_accepted, {AddrString}),
+           ?INFO("thrift connection accepted from ~s", [AddrString]),
 
            %% start_new(tSocket, [])
            Client = oop:start_new(tSocket, []),
@@ -91,9 +91,9 @@ accept(This, ListenSocket, GP, Handler) ->
 
            case receive_loop(This, Processor, Prot, Prot) of
                conn_timeout ->
-                   ?INFO(conn_timeout, {AddrString});
+                   ?INFO("thrift connection timed out from ~s", [AddrString]);
                conn_closed ->
-                   ?INFO(conn_closed, {AddrString});
+                   ?INFO("thrift connection closed from ~s", [AddrString]);
                {Class, Else} ->
                    ?ERROR("unhandled ~p in tErlAcceptor: ~p", [Class, Else])
            end,
@@ -108,10 +108,10 @@ receive_loop(This, Processor, Iprot, Oprot) ->
     try ?R2(Processor, process, Iprot, Oprot) of
        {error, TAE} when is_record(TAE, tApplicationException),
                          TAE#tApplicationException.type == ?tApplicationException_HANDLER_ERROR ->
-           ?ERROR("handler returned an error: ~p", [oop:get(TAE, message)]),
+           ?ERROR("thrift handler returned an error: ~p", [oop:get(TAE, message)]),
            receive_loop(This, Processor, Iprot, Oprot);
        Value ->
-           ?INFO(req_processed, {Value}),
+           ?INFO("thrift request: ~p", [Value]),
            receive_loop(This, Processor, Iprot, Oprot)
     catch
        exit:{timeout, _} ->