From 699fc831d15fcc4b88145798fc153ebd5bf79d94 Mon Sep 17 00:00:00 2001 From: Yosuke Hara Date: Tue, 31 Jan 2017 14:44:00 +0900 Subject: [PATCH] storage: To restrict outputing access-logs for fixing leo-project/leofs/issues/593 --- apps/leo_storage/include/leo_storage.hrl | 299 +++++++++++------- apps/leo_storage/priv/leo_storage.conf | 5 + apps/leo_storage/priv/leo_storage.schema | 13 +- .../src/leo_storage_handler_object.erl | 29 +- 4 files changed, 215 insertions(+), 131 deletions(-) diff --git a/apps/leo_storage/include/leo_storage.hrl b/apps/leo_storage/include/leo_storage.hrl index c2093e57..29b5c2bb 100644 --- a/apps/leo_storage/include/leo_storage.hrl +++ b/apps/leo_storage/include/leo_storage.hrl @@ -538,133 +538,200 @@ -define(LOG_ID_ACCESS, 'log_id_access_log'). -define(LOG_FILENAME_ACCESS, "access"). --define(access_log_get(Key, Size, ReqId, Begin, Msg), +-define(ACC_LOG_L_OK, 0). +-define(ACC_LOG_L_ERROR, 1). + +-define(env_access_log_level(), + case application:get_env(leo_storage, access_log_level) of + {ok, EnvAccessLogLevel} -> + EnvAccessLogLevel; + _ -> + ?ACC_LOG_L_OK + end). + +-define(can_output_access_log(_Case), + case _Case of + ?ACC_LOG_L_OK -> + true; + _ -> + ?env_access_log_level() == ?ACC_LOG_L_ERROR + end). + +-define(access_log_get(_Key,_Size,_ReqId,_Begin,_Msg), + ?access_log_get(?ACC_LOG_L_OK,_Key,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_get(_Case,_Key,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[GET]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_storage_get(Key, Size, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[GET]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_storage_get(_Key,_Size,_Begin,_Msg), + ?access_log_storage_get(?ACC_LOG_L_OK,_Key,_Size,_Begin,_Msg)). +-define(access_log_storage_get(_Case,_Key,_Size,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[GET]\t[Storage]\t~s\t~w\t\t~s\t~w\t~w\t~p\n", - message = [Key, - Size, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_range_get(Key, Start, End, Size, ReqId, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[GET]\t[Storage]\t~s\t~w\t\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_range_get(_Key,_Start,_End,_Size,_ReqId,_Begin,_Msg), + ?access_log_range_get(?ACC_LOG_L_OK,_Key,_Start,_End,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_range_get(_Case,_Key,_Start,_End,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[GET]\t[Gateway]\t~s[~w-~w]\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - Start, - End, - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_storage_put(Method, Key, Size, ReqId, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[GET]\t[Gateway]\t~s[~w-~w]\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Start, + _End, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_storage_put(_Method,_Key,_Size,_ReqId,_Begin,_Msg), + ?access_log_storage_put(?ACC_LOG_L_OK,_Method,_Key,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_storage_put(_Case,_Method,_Key,_Size,_ReqId,_Begin,_Msg), begin - case Method of + case _Method of ?CMD_DELETE -> - ?access_log_storage_delete(Key, Size, ReqId, Begin, Msg); + ?access_log_storage_delete(_Case,_Key,_Size,_ReqId,_Begin,_Msg); ?CMD_PUT -> - ?access_log_storage_put(Key, Size, ReqId, Begin, Msg) + ?access_log_storage_put_1(_Case,_Key,_Size,_ReqId,_Begin,_Msg) end end). --define(access_log_storage_delete(Key, Size, ReqId, Begin, Msg), +-define(access_log_storage_delete(_Key,_Size,_ReqId,_Begin,_Msg), + ?access_log_storage_delete(?ACC_LOG_L_OK,_Key,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_storage_delete(_Case,_Key,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[DEL]\t[Storage]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_storage_put(Key, Size, ReqId, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[DEL]\t[Storage]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_storage_put_1(_Case,_Key,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[PUT]\t[Storage]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_put(Key, Size, ReqId, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[PUT]\t[Storage]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_put(_Key,_Size,_ReqId,_Begin,_Msg), + ?access_log_put(?ACC_LOG_L_OK,_Key,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_put(_Case,_Key,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[PUT]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) - end). - --define(access_log_delete(Key, Size, ReqId, Begin, Msg), + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[PUT]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end + end). + +-define(access_log_delete(_Key,_Size,_ReqId,_Begin,_Msg), + ?access_log_delete(?ACC_LOG_L_OK,_Key,_Size,_ReqId,_Begin,_Msg)). +-define(access_log_delete(_Case,_Key,_Size,_ReqId,_Begin,_Msg), begin - Latency = erlang:round((leo_date:clock() - Begin) / 1000), - leo_logger_client_base:append( - {?LOG_ID_ACCESS, - #message_log{ format = "[DEL]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", - message = [Key, - - Size, - ReqId, - leo_date:date_format(), - leo_date:clock(), - Latency, - Msg - ]} - }) + case ?can_output_access_log(_Case) of + true -> + _Latency = erlang:round((leo_date:clock() - _Begin) / 1000), + leo_logger_client_base:append( + {?LOG_ID_ACCESS, + #message_log{ format = "[DEL]\t[Gateway]\t~s\t~w\t~w\t~s\t~w\t~w\t~p\n", + message = [_Key, + _Size, + _ReqId, + leo_date:date_format(), + leo_date:clock(), + _Latency, + _Msg + ]} + }); + false -> + ok + end end). diff --git a/apps/leo_storage/priv/leo_storage.conf b/apps/leo_storage/priv/leo_storage.conf index 3024dd06..abc2537b 100644 --- a/apps/leo_storage/priv/leo_storage.conf +++ b/apps/leo_storage/priv/leo_storage.conf @@ -281,6 +281,11 @@ log.log_level = 1 ## Is enable access-log [true, false] ## log.is_enable_access_log = false +## Access log's level +## - 0: only regular case +## - 1: includes error cases +## log.access_log_level = 0 + ## Output log file(s) - Erlang's log ## log.erlang = ./log/erlang diff --git a/apps/leo_storage/priv/leo_storage.schema b/apps/leo_storage/priv/leo_storage.schema index d7bef249..d29829ce 100644 --- a/apps/leo_storage/priv/leo_storage.schema +++ b/apps/leo_storage/priv/leo_storage.schema @@ -885,7 +885,7 @@ {default, 1} ]}. -%% @doc Is enable access log +%% @doc Is enable Access log {mapping, "log.is_enable_access_log", "leo_storage.is_enable_access_log", @@ -894,6 +894,17 @@ {default, false} ]}. +%% @doc Access log's level +{mapping, + "log.access_log_level", + "leo_storage.access_log_level", + [ + %% 0: only regular case + %% 1: includes error cases + {datatype, integer}, + {default, 0} + ]}. + %% @doc Output log file(s) - erlang {mapping, "log.erlang", diff --git a/apps/leo_storage/src/leo_storage_handler_object.erl b/apps/leo_storage/src/leo_storage_handler_object.erl index bd1d5f77..0d1021ef 100644 --- a/apps/leo_storage/src/leo_storage_handler_object.erl +++ b/apps/leo_storage/src/leo_storage_handler_object.erl @@ -80,14 +80,14 @@ get({Ref, Key}) -> ?access_log_storage_get(Key, byte_size(Bin), BeginTime, ok), {ok, Ref, Metadata, Bin}; {error, Cause} -> - ?access_log_storage_get(Key, 0, BeginTime, error), + ?access_log_storage_get(?ACC_LOG_L_ERROR, Key, 0, BeginTime, error), ?error("get/1", [{from, storage}, {method, get}, {key, Key}, {cause, Cause}]), {error, Ref, Cause} end; _ -> Cause = ?ERROR_COULD_NOT_GET_REDUNDANCY, - ?access_log_storage_get(Key, 0, BeginTime, {error, Cause}), + ?access_log_storage_get(?ACC_LOG_L_ERROR, Key, 0, BeginTime, {error, Cause}), ?error("get/1", [{from, storage}, {method, get}, {key, Key}, {cause, Cause}]), {error, Ref, Cause} @@ -112,7 +112,8 @@ get(#read_parameter{addr_id = AddrId} = ReadParameter,_Redundancies) -> Redundancies); _Error -> Cause = ?ERROR_COULD_NOT_GET_REDUNDANCY, - ?access_log_storage_get(ReadParameter#read_parameter.key, 0, BeginTime, {error, Cause}), + ?access_log_storage_get(?ACC_LOG_L_ERROR, ReadParameter#read_parameter.key, 0, + BeginTime, {error, Cause}), ?error("get/2", [{from, storage}, {method, get}, {key, ReadParameter#read_parameter.key}, {cause, Cause}]), @@ -136,9 +137,9 @@ get(AddrId, Key, ReqId) -> {ok, _, Bin} -> ?access_log_get(Key, byte_size(Bin), ReqId, BeginTime, ok); {error, Reply = not_found} -> - ?access_log_get(Key, 0, ReqId, BeginTime, Reply); + ?access_log_get(?ACC_LOG_L_ERROR, Key, 0, ReqId, BeginTime, Reply); {error, Cause} -> - ?access_log_get(Key, 0, ReqId, BeginTime, error), + ?access_log_get(?ACC_LOG_L_ERROR, Key, 0, ReqId, BeginTime, error), ?error("get/3", [{from, gateway}, {method, get}, {key, Key}, {req_id, ReqId}, {cause, Cause}]) end, @@ -166,9 +167,9 @@ get(AddrId, Key, ETag, ReqId) -> {ok, _, Bin} -> ?access_log_get(Key, byte_size(Bin), ReqId, BeginTime, ok); {error, Reply = not_found} -> - ?access_log_get(Key, 0, ReqId, BeginTime, Reply); + ?access_log_get(?ACC_LOG_L_ERROR, Key, 0, ReqId, BeginTime, Reply); {error, Cause} -> - ?access_log_get(Key, 0, ReqId, BeginTime, error), + ?access_log_get(?ACC_LOG_L_ERROR, Key, 0, ReqId, BeginTime, error), ?error("get/4", [{from, gateway}, {method, get}, {key, Key}, {req_id, ReqId}, {etag, ETag}, {cause, Cause}]) end, @@ -196,9 +197,9 @@ get(AddrId, Key, StartPos, EndPos, ReqId) -> {ok, _, Bin} -> ?access_log_range_get(Key, StartPos, EndPos, byte_size(Bin), ReqId, BeginTime, ok); {error, Reply = not_found} -> - ?access_log_get(Key, 0, ReqId, BeginTime, Reply); + ?access_log_get(?ACC_LOG_L_ERROR, Key, 0, ReqId, BeginTime, Reply); {error, Cause} -> - ?access_log_range_get(Key, StartPos, EndPos, 0, ReqId, BeginTime, error), + ?access_log_range_get(?ACC_LOG_L_ERROR, Key, StartPos, EndPos, 0, ReqId, BeginTime, error), ?error("get/5", [{from, gateway}, {method, get}, {key, Key}, {req_id, ReqId}, {start_pos, StartPos}, {end_pos, EndPos}, {cause, Cause}]) @@ -314,7 +315,7 @@ put(Object, ReqId) -> {ok, _} -> ?access_log_put(Object#?OBJECT.key, Object#?OBJECT.dsize, ReqId, BeginTime, ok); {error, Cause} -> - ?access_log_put(Object#?OBJECT.key, Object#?OBJECT.dsize, ReqId, BeginTime, error), + ?access_log_put(?ACC_LOG_L_ERROR, Object#?OBJECT.key, Object#?OBJECT.dsize, ReqId, BeginTime, error), ?error("put/2", [{from, gateway}, {method, put}, {key, Object#?OBJECT.key}, {req_id, ReqId}, {cause, Cause}]) end, @@ -347,10 +348,10 @@ put(Ref, From, Object, ReqId) -> erlang:send(From, {Ref, {ok, ETag}}); %% not found an object (during rebalance and delete-operation) {error, Cause = not_found} when ReqId == 0 -> - ?access_log_storage_put(Method, Key, 0, ReqId, BeginTime, Cause), + ?access_log_storage_put(?ACC_LOG_L_ERROR, Method, Key, 0, ReqId, BeginTime, Cause), erlang:send(From, {Ref, {ok, 0}}); {error, Cause} -> - ?access_log_storage_put(Method, Key, 0, ReqId, BeginTime, error), + ?access_log_storage_put(?ACC_LOG_L_ERROR, Method, Key, 0, ReqId, BeginTime, error), ?error("put/4", [{from, storage}, {method, Method}, {key, Key}, {req_id, ReqId}, {cause, Cause}]), erlang:send(From, {Ref, {error, {node(), Cause}}}) @@ -494,10 +495,10 @@ delete(Object, ReqId, CheckUnderDir) -> ?access_log_delete(Key, Object#?OBJECT.dsize, ReqId, BeginTime, ok), delete_1(ok, Object, CheckUnderDir); {error, Cause = not_found} -> - ?access_log_delete(Key, Object#?OBJECT.dsize, ReqId, BeginTime, Cause), + ?access_log_delete(?ACC_LOG_L_ERROR, Key, Object#?OBJECT.dsize, ReqId, BeginTime, Cause), delete_1({error, Cause}, Object, CheckUnderDir); {error, Cause} -> - ?access_log_delete(Key, Object#?OBJECT.dsize, ReqId, BeginTime, error), + ?access_log_delete(?ACC_LOG_L_ERROR, Key, Object#?OBJECT.dsize, ReqId, BeginTime, error), ?error("delete/3", [{from, gateway}, {method, del}, {key, Object#?OBJECT.key}, {req_id, ReqId}, {cause, Cause}]), {error, Cause}