aboutsummaryrefslogblamecommitdiffstats
path: root/lib/kernel/src/logger_h_common.erl
blob: e69f6de38d22048c72ff2495c421ca27950acdc4 (plain) (tree)
1
2
3
4


                   
                                                        















                                                                           
                       



                                
      
                      
 


                                                                            







                                                                        













                                                

                                                                    
       
 
                                                       

                                 
 


                                                                    
                                             
                                                                    

                                                                  

                                                                   




                                                                             
                                                                     

                                                               








                                                                    
                                                                     


                                                   
               








                                                                     
                                     





                                                                    
                                                              

                                                    


                                                                


                                                                   


                                                                      




                                             
                                       





                                                                           
























                                                                                 













                                                                    
                                                   

                                                          
                                                     
                                          
                             






                                                                    
                             
   

                                                                   
   

                                                                     

                                                                            

                           

                                                                    




                                                         
                       
                                                                   
                                               


                                                                            



                 



                                                                      
                                                           
                                  
 

                       
                                      
                      










                                                                
                
                 

        






                                                                  


                                                                

                                                                   


                                                 
        



                                                                         
                                                                     
                                                                         
 




                                                                                  


                                                                    




                                                    
                                            
            
                            
                      
                  

                                                                    
            





                                                                     
 


                                                                                  
 
                                                  
                                                                                 


















                                                                      
                                        
                                                     




                                      

                                                                                
 


                                                                    



                                                               


                                 



                                                                    
                                                              





                                                                            

                                                      





                                                                             



                                                    

                                                          

                                                                    
                                          

                                                      
                                        









                                                                           

                                                                               
                                                       

                                

                                                             
                                                 


                                                           







                                                               
                                                 

                                                                               
                                            








                                                                 







                                                

                                                                    
                                           
                                              
 








                                                             
                                                             
 















                                                                    

                               






                                                                           
%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2017-2018. All Rights Reserved.
%%
%% Licensed under the Apache License, Version 2.0 (the "License");
%% you may not use this file except in compliance with the License.
%% You may obtain a copy of the License at
%%
%%     http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing, software
%% distributed under the License is distributed on an "AS IS" BASIS,
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
%% See the License for the specific language governing permissions and
%% limitations under the License.
%%
%% %CopyrightEnd%
%%
-module(logger_h_common).
-behaviour(gen_server).

-include("logger_h_common.hrl").
-include("logger_internal.hrl").

%% API
-export([filesync/2]).

%% logger_olp callbacks
-export([init/1, handle_load/2, handle_call/3, handle_cast/2, handle_info/2,
         terminate/2, code_change/3, notify/2, reset_state/1]).

%% logger callbacks
-export([log/2, adding_handler/1, removing_handler/1, changing_config/3,
         filter_config/1]).

%% Library functions for handlers
-export([error_notify/1]).

-define(OLP_KEYS,[sync_mode_qlen,
                  drop_mode_qlen,
                  flush_qlen,
                  burst_limit_enable,
                  burst_limit_max_count,
                  burst_limit_window_time,
                  overload_kill_enable,
                  overload_kill_qlen,
                  overload_kill_mem_size,
                  overload_kill_restart_after]).

-define(COMMON_KEYS,[filesync_repeat_interval]).

-define(READ_ONLY_KEYS,[olp]).

%%%-----------------------------------------------------------------
%%% API

%% This function is called by the logger_sup supervisor
filesync(Module, Name) ->
    call(Module, Name, filesync).

%%%-----------------------------------------------------------------
%%% Handler being added
adding_handler(#{id:=Name,module:=Module}=Config) ->
    HConfig0 = maps:get(config, Config, #{}),
    HandlerConfig0 = maps:without(?OLP_KEYS++?COMMON_KEYS,HConfig0),
    case Module:check_config(Name,set,undefined,HandlerConfig0) of
        {ok,HandlerConfig} ->
            ModifiedCommon = maps:with(?COMMON_KEYS,HandlerConfig),
            CommonConfig0 = maps:with(?COMMON_KEYS,HConfig0),
            CommonConfig = maps:merge(
                             maps:merge(get_default_config(), CommonConfig0),
                             ModifiedCommon),
            case check_config(CommonConfig) of
                ok ->
                    HConfig = maps:merge(CommonConfig,HandlerConfig),
                    OlpOpts = maps:with(?OLP_KEYS,HConfig0),
                    start(OlpOpts, Config#{config => HConfig});
                {error,Faulty} ->
                    {error,{invalid_config,Module,Faulty}}
            end;
        Error ->
            Error
    end.

%%%-----------------------------------------------------------------
%%% Handler being removed
removing_handler(#{id:=Name, module:=Module, config:=#{olp:=Olp}}) ->
    case whereis(?name_to_reg_name(Module,Name)) of
        undefined ->
            ok;
        _Pid ->
            %% We don't want to do supervisor:terminate_child here
            %% since we need to distinguish this explicit stop from a
            %% system termination in order to avoid circular attempts
            %% at removing the handler (implying deadlocks and
            %% timeouts).
            %% And we don't need to do supervisor:delete_child, since
            %% the restart type is temporary, which means that the
            %% child specification is automatically removed from the
            %% supervisor when the process dies.
            _ = logger_olp:stop(Olp),
            ok
    end.

%%%-----------------------------------------------------------------
%%% Updating handler config
changing_config(SetOrUpdate,
                #{id:=Name,config:=OldHConfig,module:=Module},
                NewConfig0) ->
    NewHConfig0 = maps:get(config, NewConfig0, #{}),
    NoHandlerKeys = ?OLP_KEYS++?COMMON_KEYS++?READ_ONLY_KEYS,
    OldHandlerConfig = maps:without(NoHandlerKeys,OldHConfig),
    NewHandlerConfig0 = maps:without(NoHandlerKeys,NewHConfig0),
    case Module:check_config(Name, SetOrUpdate,
                             OldHandlerConfig,NewHandlerConfig0) of
        {ok, NewHandlerConfig} ->
            ModifiedCommon = maps:with(?COMMON_KEYS,NewHandlerConfig),
            NewCommonConfig0 = maps:with(?COMMON_KEYS,NewHConfig0),
            OldCommonConfig = maps:with(?COMMON_KEYS,OldHConfig),
            CommonDefault =
                case SetOrUpdate of
                    set ->
                        get_default_config();
                    update ->
                        OldCommonConfig
                end,
            NewCommonConfig = maps:merge(
                                maps:merge(CommonDefault,NewCommonConfig0),
                                ModifiedCommon),
            case check_config(NewCommonConfig) of
                ok ->
                    OlpDefault =
                        case SetOrUpdate of
                            set ->
                                logger_olp:get_default_opts();
                            update ->
                                maps:with(?OLP_KEYS,OldHConfig)
                        end,
                    Olp = maps:get(olp,OldHConfig),
                    NewOlpOpts = maps:merge(OlpDefault,
                                            maps:with(?OLP_KEYS,NewHConfig0)),
                    case logger_olp:set_opts(Olp,NewOlpOpts) of
                        ok ->
                            maybe_set_repeated_filesync(Olp,OldCommonConfig,
                                                        NewCommonConfig),
                            ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig),
                            NewHConfig =
                                maps:merge(
                                  maps:merge(
                                    maps:merge(NewCommonConfig,NewHandlerConfig),
                                    ReadOnly),
                                  NewOlpOpts),
                            NewConfig = NewConfig0#{config=>NewHConfig},
                            {ok,NewConfig};
                        Error  ->
                            Error
                    end;
                {error,Faulty} ->
                    {error,{invalid_config,Module,Faulty}}
            end;
        Error ->
            Error
    end.

%%%-----------------------------------------------------------------
%%% Log a string or report
-spec log(LogEvent, Config) -> ok when
      LogEvent :: logger:log_event(),
      Config :: logger:handler_config().

log(LogEvent, Config = #{config := #{olp:=Olp}}) ->
    %% if the handler has crashed, we must drop this event
    %% and hope the handler restarts so we can try again
    true = is_process_alive(logger_olp:get_pid(Olp)),
    Bin = log_to_binary(LogEvent, Config),
    logger_olp:load(Olp,Bin).

%%%-----------------------------------------------------------------
%%% Remove internal fields from configuration
filter_config(#{config:=HConfig}=Config) ->
    Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}.

%%%-----------------------------------------------------------------
%%% Start the handler process
%%%
%%% The process must always exist if the handler is registered with
%%% logger (and must not exist if the handler is not registered).
%%%
%%% The handler process is linked to logger_sup, which is part of the
%%% kernel application's supervision tree.
start(OlpOpts0, #{id := Name, module:=Module, config:=HConfig} = Config0) ->
    RegName = ?name_to_reg_name(Module,Name),
    ChildSpec =
        #{id       => Name,
          start    => {logger_olp, start_link, [RegName,?MODULE,
                                                Config0, OlpOpts0]},
          restart  => temporary,
          shutdown => 2000,
          type     => worker,
          modules  => [?MODULE]},
    case supervisor:start_child(logger_sup, ChildSpec) of
        {ok,Pid,Olp} ->
            ok = logger_handler_watcher:register_handler(Name,Pid),
            OlpOpts = logger_olp:get_opts(Olp),
            {ok,Config0#{config=>(maps:merge(HConfig,OlpOpts))#{olp=>Olp}}};
        {error,{Reason,Ch}} when is_tuple(Ch), element(1,Ch)==child ->
            {error,Reason};
        Error ->
            Error
    end.

%%%===================================================================
%%% gen_server callbacks
%%%===================================================================

init(#{id := Name, module := Module, config := HConfig}) ->
    process_flag(trap_exit, true),

    ?init_test_hooks(),

    case Module:init(Name, HConfig) of
        {ok,HState} ->
            %% Storing common config in state to avoid copying
            %% (sending) the config data for each log message
            CommonConfig = maps:with(?COMMON_KEYS,HConfig),
            State = CommonConfig#{id => Name,
                                  module => Module,
                                  ctrl_sync_count =>
                                      ?CONTROLLER_SYNC_INTERVAL,
                                  last_op => sync,
                                  handler_state => HState},
            State1 = set_repeated_filesync(State),
            {ok,State1};
        Error ->
            Error
    end.

%% This is the log event.
handle_load(Bin, #{id:=Name,
                   module:=Module,
                   handler_state:=HandlerState,
                   ctrl_sync_count := CtrlSync}=State) ->
    if CtrlSync==0 ->
            {_,HS1} = Module:write(Name, sync, Bin, HandlerState),
            State#{handler_state => HS1,
                   ctrl_sync_count => ?CONTROLLER_SYNC_INTERVAL,
                   last_op=>write};
       true ->
            {_,HS1} = Module:write(Name, async, Bin, HandlerState),
            State#{handler_state => HS1,
                   ctrl_sync_count => CtrlSync-1,
                   last_op=>write}
    end.

handle_call(filesync, _From, State = #{id := Name,
                                       module := Module,
                                       handler_state := HandlerState}) ->
    {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState),
    {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}.

%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this
%% clause gets called repeatedly by the handler. In order to
%% guarantee that a filesync *always* happens after the last log
%% event, the repeat operation must be active!
handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) ->
    %% This clause handles a race condition which may occur when
    %% config changes filesync_repeat_interval from an integer value
    %% to no_repeat.
    {noreply,State};
handle_cast(repeated_filesync,
            State = #{id := Name,
                      module := Module,
                      handler_state := HandlerState,
                      last_op := LastOp}) ->
    State1 =
        if LastOp == sync ->
                State;
           true ->
                {_,HS} = Module:filesync(Name, async, HandlerState),
                State#{handler_state => HS, last_op => sync}
        end,
    {noreply,set_repeated_filesync(State1)};

handle_cast({set_repeated_filesync,FSyncInt},State) ->
    State1 = State#{filesync_repeat_interval=>FSyncInt},
    State2 = set_repeated_filesync(cancel_repeated_filesync(State1)),
    {noreply, State2}.

handle_info(Info, #{id := Name, module := Module,
                    handler_state := HandlerState} = State) ->
    {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}.

terminate(overloaded=Reason, #{id:=Name}=State) ->
    _ = log_handler_info(Name,"Handler ~p overloaded and stopping",[Name],State),
    do_terminate(Reason,State),
    ConfigResult = logger:get_handler_config(Name),
    case ConfigResult of
        {ok,#{module:=Module}=HConfig0} ->
            spawn(fun() -> logger:remove_handler(Name) end),
            HConfig = try Module:filter_config(HConfig0)
                      catch _:_ -> HConfig0
                      end,
            {ok,fun() -> logger:add_handler(Name,Module,HConfig) end};
        Error ->
            error_notify({Name,restart_impossible,Error}),
            Error
    end;
terminate(Reason, State) ->
    do_terminate(Reason, State).

do_terminate(Reason, State = #{id := Name,
                               module := Module,
                               handler_state := HandlerState}) ->
    _ = cancel_repeated_filesync(State),
    _ = Module:terminate(Name, Reason, HandlerState),
    ok.

code_change(_OldVsn, State, _Extra) ->
    {ok, State}.

reset_state(#{id:=Name, module:=Module, handler_state:=HandlerState} = State) ->
    State#{handler_state=>Module:reset_state(Name, HandlerState)}.

%%%-----------------------------------------------------------------
%%% Internal functions
call(Module, Name, Op) when is_atom(Name) ->
    case logger_olp:call(?name_to_reg_name(Module,Name), Op) of
        {error,busy} -> {error,handler_busy};
        Other -> Other
    end;
call(_, Name, Op) ->
    {error,{badarg,{Op,[Name]}}}.

notify({mode_change,Mode0,Mode1},#{id:=Name}=State) ->
    log_handler_info(Name,"Handler ~p switched from  ~p to ~p mode",
                     [Name,Mode0,Mode1], State);
notify({flushed,Flushed},#{id:=Name}=State) ->
    log_handler_info(Name, "Handler ~p flushed ~w log events",
                     [Name,Flushed], State);
notify(restart,#{id:=Name}=State) ->
    log_handler_info(Name, "Handler ~p restarted", [Name], State);
notify(idle,#{id:=Name,module:=Module,handler_state:=HandlerState}=State) ->
    {_,HS} = Module:filesync(Name,async,HandlerState),
    State#{handler_state=>HS, last_op=>sync}.

log_handler_info(Name, Format, Args, #{module:=Module,
                                       handler_state:=HandlerState}=State) ->
    Config =
        case logger:get_handler_config(Name) of
            {ok,Conf} -> Conf;
            _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}
        end,
    Meta = #{time=>erlang:system_time(microsecond)},
    Bin = log_to_binary(#{level => notice,
                          msg => {Format,Args},
                          meta => Meta}, Config),
    {_,HS} = Module:write(Name, async, Bin, HandlerState),
    State#{handler_state=>HS, last_op=>write}.

%%%-----------------------------------------------------------------
%%% Convert log data on any form to binary
-spec log_to_binary(LogEvent,Config) -> LogString when
      LogEvent :: logger:log_event(),
      Config :: logger:handler_config(),
      LogString :: binary().
log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) ->
    do_log_to_binary(Log,Config);
log_to_binary(#{msg:={report,_},meta:=Meta}=Log,Config) ->
    DefaultReportCb = fun logger:format_otp_report/1,
    do_log_to_binary(Log#{meta=>Meta#{report_cb=>DefaultReportCb}},Config);
log_to_binary(Log,Config) ->
    do_log_to_binary(Log,Config).

do_log_to_binary(Log,Config) ->
    {Formatter,FormatterConfig} =
        maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}),
    String = try_format(Log,Formatter,FormatterConfig),
    try string_to_binary(String)
    catch C2:R2:S2 ->
            ?LOG_INTERNAL(debug,[{formatter_error,Formatter},
                                 {config,FormatterConfig},
                                 {log_event,Log},
                                 {bad_return_value,String},
                                 {catched,{C2,R2,S2}}]),
            <<"FORMATTER ERROR: bad return value">>
    end.

try_format(Log,Formatter,FormatterConfig) ->
    try Formatter:format(Log,FormatterConfig)
    catch
        C:R:S ->
            ?LOG_INTERNAL(debug,[{formatter_crashed,Formatter},
                                 {config,FormatterConfig},
                                 {log_event,Log},
                                 {reason,
                                  {C,R,logger:filter_stacktrace(?MODULE,S)}}]),
            case {?DEFAULT_FORMATTER,#{}} of
                {Formatter,FormatterConfig} ->
                    "DEFAULT FORMATTER CRASHED";
                {DefaultFormatter,DefaultConfig} ->
                    try_format(Log#{msg=>{"FORMATTER CRASH: ~tp",
                                          [maps:get(msg,Log)]}},
                              DefaultFormatter,DefaultConfig)
            end
    end.

string_to_binary(String) ->
    case unicode:characters_to_binary(String) of
        Binary when is_binary(Binary) ->
            Binary;
        Error ->
            throw(Error)
    end.

%%%-----------------------------------------------------------------
%%% Check that the configuration term is valid
check_config(Config) when is_map(Config) ->
    check_common_config(maps:to_list(Config)).

check_common_config([{filesync_repeat_interval,NorA}|Config])
  when is_integer(NorA); NorA == no_repeat ->
    check_common_config(Config);
check_common_config([{Key,Value}|_]) ->
    {error,#{Key=>Value}};
check_common_config([]) ->
    ok.

get_default_config() ->
    #{filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}.

set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State)
  when is_integer(FSyncInt) ->
    {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast,
                                  [self(),repeated_filesync]),
    State#{rep_sync_tref=>TRef};
set_repeated_filesync(State) ->
    State.

cancel_repeated_filesync(State) ->
    case maps:take(rep_sync_tref,State) of
        {TRef,State1} ->
            _ = timer:cancel(TRef),
            State1;
        error ->
            State
    end.
error_notify(Term) ->
    ?internal_log(error, Term).

maybe_set_repeated_filesync(_Olp,
                            #{filesync_repeat_interval:=FSyncInt},
                            #{filesync_repeat_interval:=FSyncInt}) ->
    ok;
maybe_set_repeated_filesync(Olp,_,#{filesync_repeat_interval:=FSyncInt}) ->
    logger_olp:cast(Olp,{set_repeated_filesync,FSyncInt}).