From 2c81b56377de25efed85d5948d080bff49758927 Mon Sep 17 00:00:00 2001 From: zmstone Date: Wed, 20 Mar 2024 11:10:13 +0100 Subject: [PATCH] feat: add authentication_failure throttled log also included changes: 1. add 'username' to log metadata 2. add 'tag' to authz warning logs --- apps/emqx/src/emqx_access_control.erl | 28 ++++++++++++++----------- apps/emqx/src/emqx_channel.erl | 23 ++++++++++++++++---- apps/emqx/src/emqx_logger.erl | 7 +++++++ apps/emqx/src/emqx_logger_textfmt.erl | 4 +++- apps/emqx_conf/src/emqx_conf_schema.erl | 1 + 5 files changed, 46 insertions(+), 17 deletions(-) diff --git a/apps/emqx/src/emqx_access_control.erl b/apps/emqx/src/emqx_access_control.erl index 64ea1a741..016386011 100644 --- a/apps/emqx/src/emqx_access_control.erl +++ b/apps/emqx/src/emqx_access_control.erl @@ -154,7 +154,7 @@ do_authorize(ClientInfo, Action, Topic) -> case run_hooks('client.authorize', [ClientInfo, Action, Topic], Default) of AuthzResult = #{result := Result} when Result == allow; Result == deny -> From = maps:get(from, AuthzResult, unknown), - ok = log_result(ClientInfo, Topic, Action, From, Result), + ok = log_result(Topic, Action, From, Result), emqx_hooks:run( 'client.check_authz_complete', [ClientInfo, Action, Topic, Result, From] @@ -173,24 +173,28 @@ do_authorize(ClientInfo, Action, Topic) -> deny end. -log_result(#{username := Username}, Topic, Action, From, Result) -> +log_result(Topic, Action, From, Result) -> LogMeta = fun() -> #{ - username => Username, topic => Topic, action => format_action(Action), source => format_from(From) } end, - case Result of - allow -> - ?SLOG(info, (LogMeta())#{msg => "authorization_permission_allowed"}); - deny -> - ?SLOG_THROTTLE( - warning, - (LogMeta())#{msg => authorization_permission_denied} - ) - end. + do_log_result(Action, Result, LogMeta). + +do_log_result(_Action, allow, LogMeta) -> + ?SLOG(info, (LogMeta())#{msg => "authorization_permission_allowed"}, #{tag => "AUTHZ"}); +do_log_result(?AUTHZ_PUBLISH_MATCH_MAP(_, _), deny, LogMeta) -> + %% for publish action, we do not log permission deny at warning level here + %% because it will be logged as cannot_publish_to_topic_due_to_not_authorized + ?SLOG(info, (LogMeta())#{msg => "authorization_permission_denied"}, #{tag => "AUTHZ"}); +do_log_result(_, deny, LogMeta) -> + ?SLOG_THROTTLE( + warning, + (LogMeta())#{msg => authorization_permission_denied}, + #{tag => "AUTHZ"} + ). %% @private Format authorization rules source. format_from(default) -> diff --git a/apps/emqx/src/emqx_channel.erl b/apps/emqx/src/emqx_channel.erl index bc0bf18ea..c0971c29a 100644 --- a/apps/emqx/src/emqx_channel.erl +++ b/apps/emqx/src/emqx_channel.erl @@ -633,7 +633,7 @@ process_publish(Packet = ?PUBLISH_PACKET(QoS, Topic, PacketId), Channel) -> msg => cannot_publish_to_topic_due_to_not_authorized, reason => emqx_reason_codes:name(Rc) }, - #{topic => Topic} + #{topic => Topic, tag => "AUTHZ"} ), case emqx:get_config([authorization, deny_action], ignore) of ignore -> @@ -652,7 +652,7 @@ process_publish(Packet = ?PUBLISH_PACKET(QoS, Topic, PacketId), Channel) -> msg => cannot_publish_to_topic_due_to_quota_exceeded, reason => emqx_reason_codes:name(Rc) }, - #{topic => Topic} + #{topic => Topic, tag => "AUTHZ"} ), case QoS of ?QOS_0 -> @@ -1612,8 +1612,10 @@ fix_mountpoint(_ConnPkt, ClientInfo = #{mountpoint := MountPoint}) -> %%-------------------------------------------------------------------- %% Set log metadata -set_log_meta(_ConnPkt, #channel{clientinfo = #{clientid := ClientId}}) -> - emqx_logger:set_metadata_clientid(ClientId). +set_log_meta(_ConnPkt, #channel{clientinfo = #{clientid := ClientId} = ClientInfo}) -> + Username = maps:get(username, ClientInfo, undefined), + emqx_logger:set_metadata_clientid(ClientId), + emqx_logger:set_metadata_username(Username). %%-------------------------------------------------------------------- %% Check banned @@ -1680,6 +1682,7 @@ authenticate( Channel ); _ -> + log_auth_failure("bad_authentication_method"), {error, ?RC_BAD_AUTHENTICATION_METHOD} end. @@ -1706,6 +1709,7 @@ do_authenticate( auth_cache = AuthCache }}; {error, Reason} -> + log_auth_failure(Reason), {error, emqx_reason_codes:connack_error(Reason)} end; do_authenticate(Credential, #channel{clientinfo = ClientInfo} = Channel) -> @@ -1713,9 +1717,20 @@ do_authenticate(Credential, #channel{clientinfo = ClientInfo} = Channel) -> {ok, AuthResult} -> {ok, #{}, Channel#channel{clientinfo = merge_auth_result(ClientInfo, AuthResult)}}; {error, Reason} -> + log_auth_failure(Reason), {error, emqx_reason_codes:connack_error(Reason)} end. +log_auth_failure(Reason) -> + ?SLOG_THROTTLE( + warning, + #{ + msg => authentication_failure, + reason => Reason + }, + #{tag => "AUTHN"} + ). + merge_auth_result(ClientInfo, AuthResult) when is_map(ClientInfo) andalso is_map(AuthResult) -> IsSuperuser = maps:get(is_superuser, AuthResult, false), maps:merge(ClientInfo, AuthResult#{is_superuser => IsSuperuser}). diff --git a/apps/emqx/src/emqx_logger.erl b/apps/emqx/src/emqx_logger.erl index 36e030934..247695485 100644 --- a/apps/emqx/src/emqx_logger.erl +++ b/apps/emqx/src/emqx_logger.erl @@ -43,6 +43,7 @@ -export([ set_metadata_peername/1, set_metadata_clientid/1, + set_metadata_username/1, set_proc_metadata/1, set_primary_log_level/1, set_log_handler_level/2, @@ -142,6 +143,12 @@ set_metadata_clientid(<<>>) -> set_metadata_clientid(ClientId) -> set_proc_metadata(#{clientid => ClientId}). +-spec set_metadata_username(emqx_types:username()) -> ok. +set_metadata_username(Username) when Username =:= undefined orelse Username =:= <<>> -> + ok; +set_metadata_username(Username) -> + set_proc_metadata(#{username => Username}). + -spec set_metadata_peername(peername_str()) -> ok. set_metadata_peername(Peername) -> set_proc_metadata(#{peername => Peername}). diff --git a/apps/emqx/src/emqx_logger_textfmt.erl b/apps/emqx/src/emqx_logger_textfmt.erl index b68c4b366..1b2ea8758 100644 --- a/apps/emqx/src/emqx_logger_textfmt.erl +++ b/apps/emqx/src/emqx_logger_textfmt.erl @@ -69,7 +69,9 @@ enrich_report(ReportRaw, Meta) -> ClientId = maps:get(clientid, Meta, undefined), Peer = maps:get(peername, Meta, undefined), Msg = maps:get(msg, ReportRaw, undefined), - Tag = maps:get(tag, ReportRaw, undefined), + %% TODO: move all tags to Meta so we can filter traces + %% based on tags (currently not supported) + Tag = maps:get(tag, ReportRaw, maps:get(tag, Meta, undefined)), %% turn it into a list so that the order of the fields is determined lists:foldl( fun diff --git a/apps/emqx_conf/src/emqx_conf_schema.erl b/apps/emqx_conf/src/emqx_conf_schema.erl index a40716b4d..c72f6a87b 100644 --- a/apps/emqx_conf/src/emqx_conf_schema.erl +++ b/apps/emqx_conf/src/emqx_conf_schema.erl @@ -78,6 +78,7 @@ -define(DEFAULT_MAX_PORTS, 1024 * 1024). -define(LOG_THROTTLING_MSGS, [ + authentication_failure, authorization_permission_denied, cannot_publish_to_topic_due_to_not_authorized, cannot_publish_to_topic_due_to_quota_exceeded,