fix(audit): correctly handle SSO related events

apps/emqx_audit/src/emqx_audit.app.src

@@ -1,6 +1,6 @@
 {application, emqx_audit, [
     {description, "Audit log for EMQX"},
-    {vsn, "0.1.0"},
+    {vsn, "0.1.1"},
     {registered, []},
     {mod, {emqx_audit_app, []}},
     {applications, [kernel, stdlib, emqx]},

apps/emqx_audit/src/emqx_audit.erl

@@ -50,7 +50,24 @@ to_audit(#{from := cli, cmd := Cmd, args := Args, duration_ms := DurationMs}) ->
         http_method = <<"">>,
         http_request = <<"">>
     };
-to_audit(#{from := From} = Log) when From =:= dashboard orelse From =:= rest_api ->
+to_audit(#{from := erlang_console, function := F, args := Args}) ->
+    #?AUDIT{
+        from = erlang_console,
+        source = <<"">>,
+        source_ip = <<"">>,
+        %% operation info
+        operation_id = <<"">>,
+        operation_type = <<"">>,
+        operation_result = <<"">>,
+        failure = <<"">>,
+        %% request detail
+        http_status_code = <<"">>,
+        http_method = <<"">>,
+        http_request = <<"">>,
+        duration_ms = 0,
+        args = iolist_to_binary(io_lib:format("~p: ~ts", [F, Args]))
+    };
+to_audit(#{from := From} = Log) when is_atom(From) ->
     #{
         source := Source,
         source_ip := SourceIp,
@@ -79,23 +96,6 @@ to_audit(#{from := From} = Log) when From =:= dashboard orelse From =:= rest_api
         http_request = Request,
         duration_ms = DurationMs,
         args = <<"">>
-    };
-to_audit(#{from := erlang_console, function := F, args := Args}) ->
-    #?AUDIT{
-        from = erlang_console,
-        source = <<"">>,
-        source_ip = <<"">>,
-        %% operation info
-        operation_id = <<"">>,
-        operation_type = <<"">>,
-        operation_result = <<"">>,
-        failure = <<"">>,
-        %% request detail
-        http_status_code = <<"">>,
-        http_method = <<"">>,
-        http_request = <<"">>,
-        duration_ms = 0,
-        args = iolist_to_binary(io_lib:format("~p: ~ts", [F, Args]))
     }.
 
 log(_Level, undefined, _Handler) ->

apps/emqx_dashboard/src/emqx_dashboard.erl

@@ -274,7 +274,7 @@ listener_name(Protocol) ->
 
 audit_log_fun() ->
     case emqx_release:edition() of
-        ee -> fun emqx_dashboard_audit:log/2;
+        ee -> emqx_dashboard_audit:log_fun();
         ce -> undefined
     end.
 

apps/emqx_dashboard/src/emqx_dashboard_api.erl

@@ -219,6 +219,7 @@ field(backend) ->
 login(post, #{body := Params}) ->
     Username = maps:get(<<"username">>, Params),
     Password = maps:get(<<"password">>, Params),
+    minirest_handler:update_log_meta(#{log_from => dashboard, log_source => Username}),
     case emqx_dashboard_admin:sign_token(Username, Password) of
         {ok, Role, Token} ->
             ?SLOG(info, #{msg => "dashboard_login_successful", username => Username}),

apps/emqx_dashboard/src/emqx_dashboard_audit.erl

@@ -19,30 +19,47 @@
 -include_lib("emqx/include/logger.hrl").
 -include_lib("emqx/include/http_api.hrl").
 %% API
--export([log/2]).
-
-%% filter high frequency events
--define(HIGH_FREQUENCY_REQUESTS, [
-    <<"/publish">>,
-    <<"/clients/:clientid/subscribe">>,
-    <<"/clients/:clientid/unsubscribe">>,
-    <<"/publish/bulk">>,
-    <<"/clients/:clientid/unsubscribe/bulk">>,
-    <<"/clients/:clientid/subscribe/bulk">>,
-    <<"/clients/kickout/bulk">>
-]).
-
-log(#{code := Code, method := Method} = Meta, Req) ->
+-export([log/2, log_fun/0, importance/1]).
+
+%% In the previous versions,
+%% this module used the request method to determine whether the request should be logged,
+%% but here are some exceptions:
+%% 1. the OIDC callback uses the `GET` method, but it is important
+%% 2. some endpoints (called frequency requests) use the `POST` method,
+%%    but most of the time we do not want to log them
+%% So an auxiliary `importance` metadata was introduced.
+%%
+%% The strategy is:
+%% 1. Use `high` to mark an important `GET` method
+%% 2. Use `low` to mark the frequency methods
+%% 3. `medium` is the default importance and is set automatically
+
+-define(AUDIT_IMPORTANCE_HIGH, 100).
+-define(AUDIT_IMPORTANCE_MEDIUM, 60).
+-define(AUDIT_IMPORTANCE_LOW, 30).
+
+-define(CODE_METHOD_NOT_ALLOWED, 405).
+
+log_fun() ->
+    {emqx_dashboard_audit, log, #{importance => medium}}.
+
+importance(Level) when
+    Level =:= high;
+    Level =:= medium;
+    Level =:= low
+->
+    #{importance => Level}.
+
+log(#{code := Code, method := Method, importance := Importance} = Meta, Req) ->
     %% Keep level/2 and log_meta/1 inside of this ?AUDIT macro
-    ?AUDIT(level(Method, Code), log_meta(Meta, Req)).
-
-log_meta(Meta, Req) ->
-    #{operation_id := OperationId, method := Method} = Meta,
-    case
-        Method =:= get orelse
-            (lists:member(OperationId, ?HIGH_FREQUENCY_REQUESTS) andalso
-                ignore_high_frequency_request())
-    of
+    ImportanceNum = importance_to_num(Code, Importance),
+    ?AUDIT(level(ImportanceNum, Method, Code), log_meta(ImportanceNum, Meta, Req)).
+
+log_meta(Importance, #{method := get} = _Meta, _Req) when Importance =< ?AUDIT_IMPORTANCE_MEDIUM ->
+    undefined;
+log_meta(Importance, Meta, Req) ->
+    #{method := Method} = Meta,
+    case (Importance =< ?AUDIT_IMPORTANCE_LOW) andalso ignore_high_frequency_request() of
         true ->
             undefined;
         false ->
@@ -72,18 +89,20 @@ from(#{auth_type := jwt_token}) ->
     dashboard;
 from(#{auth_type := api_key}) ->
     rest_api;
-from(#{operation_id := <<"/login">>}) ->
-    dashboard;
+from(#{log_from := From}) ->
+    From;
 from(#{code := Code} = Meta) when Code =:= 401 orelse Code =:= 403 ->
     case maps:find(failure, Meta) of
         {ok, #{code := 'BAD_API_KEY_OR_SECRET'}} -> rest_api;
         {ok, #{code := 'UNAUTHORIZED_ROLE', message := ?API_KEY_NOT_ALLOW_MSG}} -> rest_api;
         %% 'TOKEN_TIME_OUT' 'BAD_TOKEN' is dashboard code.
         _ -> dashboard
-    end.
+    end;
+from(_) ->
+    unknown.
 
 source(#{source := Source}) -> Source;
-source(#{operation_id := <<"/login">>, body := #{<<"username">> := Username}}) -> Username;
+source(#{log_source := Source}) -> Source;
 source(_Meta) -> <<"">>.
 
 source_ip(Req) ->
@@ -106,15 +125,31 @@ operation_type(Meta) ->
 http_request(Meta) ->
     maps:with([method, headers, bindings, body], Meta).
 
+operation_result(302, _) -> success;
 operation_result(Code, _) when Code >= 300 -> failure;
 operation_result(_, #{failure := _}) -> failure;
 operation_result(_, _) -> success.
 
-level(get, _Code) -> debug;
-level(_, Code) when Code >= 200 andalso Code < 300 -> info;
-level(_, Code) when Code >= 300 andalso Code < 400 -> warning;
-level(_, Code) when Code >= 400 andalso Code < 500 -> error;
-level(_, _) -> critical.
+%%
+level(?AUDIT_IMPORTANCE_HIGH, _, _) -> warning;
+level(_, get, _Code) -> debug;
+level(_, _, Code) when Code >= 200 andalso Code < 300 -> info;
+level(_, _, Code) when Code >= 300 andalso Code < 400 -> warning;
+level(_, _, Code) when Code >= 400 andalso Code < 500 -> error;
+level(_, _, _) -> critical.
 
 ignore_high_frequency_request() ->
     emqx_conf:get([log, audit, ignore_high_frequency_request], true).
+
+%% This is a special case.
+%% An illegal request (e.g. A `GET` request to a `POST`-only endpoint) does not have metadata,
+%% its `importance` is the default value,
+%% so we have to manually increase the `importance` to record this request.
+importance_to_num(?CODE_METHOD_NOT_ALLOWED, _) ->
+    ?AUDIT_IMPORTANCE_HIGH;
+importance_to_num(_, high) ->
+    ?AUDIT_IMPORTANCE_HIGH;
+importance_to_num(_, medium) ->
+    ?AUDIT_IMPORTANCE_MEDIUM;
+importance_to_num(_, low) ->
+    ?AUDIT_IMPORTANCE_LOW.

apps/emqx_dashboard_sso/src/emqx_dashboard_sso.app.src

@@ -1,6 +1,6 @@
 {application, emqx_dashboard_sso, [
     {description, "EMQX Dashboard Single Sign-On"},
-    {vsn, "0.1.6"},
+    {vsn, "0.1.7"},
     {registered, [emqx_dashboard_sso_sup]},
     {applications, [
         kernel,

apps/emqx_dashboard_sso/src/emqx_dashboard_sso_api.erl

@@ -157,6 +157,7 @@ running(get, _Request) ->
     {200, emqx_dashboard_sso_manager:running()}.
 
 login(post, #{bindings := #{backend := Backend}, body := Body} = Request) ->
+    minirest_handler:update_log_meta(#{log_from => dashboard, log_source => Backend}),
     case emqx_dashboard_sso_manager:lookup_state(Backend) of
         undefined ->
             {404, #{code => ?BACKEND_NOT_FOUND, message => <<"Backend not found">>}};
@@ -168,6 +169,7 @@ login(post, #{bindings := #{backend := Backend}, body := Body} = Request) ->
                         request => emqx_utils:redact(Request)
                     }),
                     Username = maps:get(<<"username">>, Body),
+                    minirest_handler:update_log_meta(#{log_source => Username}),
                     {200, login_meta(Username, Role, Token, Backend)};
                 {redirect, Redirect} ->
                     ?SLOG(info, #{

apps/emqx_dashboard_sso/src/emqx_dashboard_sso_oidc_api.erl

@@ -67,7 +67,8 @@ schema("/sso/oidc/callback") ->
                 401 => response_schema(401),
                 404 => response_schema(404)
             },
-            security => []
+            security => [],
+            log_meta => emqx_dashboard_audit:importance(high)
         }
     }.
 
@@ -75,6 +76,7 @@ schema("/sso/oidc/callback") ->
 %% API
 %%--------------------------------------------------------------------
 code_callback(get, #{query_string := QS}) ->
+    minirest_handler:update_log_meta(#{log_from => oidc}),
     case ensure_sso_state(QS) of
         {ok, Target} ->
             ?SLOG(info, #{
@@ -185,6 +187,7 @@ retrieve_userinfo(
                 user_info => UserInfo
             }),
             Username = emqx_placeholder:proc_tmpl(NameTks, UserInfo),
+            minirest_handler:update_log_meta(#{log_source => Username}),
             ensure_user_exists(Cfg, Username);
         {error, _Reason} = Error ->
             Error

apps/emqx_dashboard_sso/src/emqx_dashboard_sso_saml.erl

@@ -240,7 +240,7 @@ gen_redirect_response(DashboardAddr, Username) ->
     case ensure_user_exists(Username) of
         {ok, Role, Token} ->
             Target = login_redirect_target(DashboardAddr, Username, Role, Token),
-            {redirect, {302, ?RESPHEADERS#{<<"location">> => Target}, ?REDIRECT_BODY}};
+            {redirect, Username, {302, ?RESPHEADERS#{<<"location">> => Target}, ?REDIRECT_BODY}};
         {error, Reason} ->
             {error, Reason}
     end.

apps/emqx_dashboard_sso/src/emqx_dashboard_sso_saml_api.erl

@@ -98,14 +98,16 @@ sp_saml_metadata(get, _Req) ->
     end.
 
 sp_saml_callback(post, Req) ->
+    minirest_handler:update_log_meta(#{log_from => saml}),
     case emqx_dashboard_sso_manager:lookup_state(saml) of
         State = #{enable := true} ->
             case (provider(saml)):callback(Req, State) of
-                {redirect, Redirect} ->
+                {redirect, Username, Redirect} ->
                     ?SLOG(info, #{
                         msg => "dashboard_saml_sso_login_successful",
                         redirect => "SAML login successful. Redirecting with LoginMeta."
                     }),
+                    minirest_handler:update_log_meta(#{log_source => Username}),
                     Redirect;
                 {error, Reason} ->
                     ?SLOG(info, #{

apps/emqx_management/src/emqx_mgmt_api_clients.erl

@@ -198,7 +198,8 @@ schema("/clients/kickout/bulk") ->
             ),
             responses => #{
                 204 => <<"Kick out clients successfully">>
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/clients/:clientid") ->
@@ -288,7 +289,8 @@ schema("/clients/:clientid/subscribe") ->
                 404 => emqx_dashboard_swagger:error_codes(
                     ['CLIENTID_NOT_FOUND'], <<"Client ID not found">>
                 )
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/clients/:clientid/subscribe/bulk") ->
@@ -304,7 +306,8 @@ schema("/clients/:clientid/subscribe/bulk") ->
                 404 => emqx_dashboard_swagger:error_codes(
                     ['CLIENTID_NOT_FOUND'], <<"Client ID not found">>
                 )
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/clients/:clientid/unsubscribe") ->
@@ -320,7 +323,8 @@ schema("/clients/:clientid/unsubscribe") ->
                 404 => emqx_dashboard_swagger:error_codes(
                     ['CLIENTID_NOT_FOUND'], <<"Client ID not found">>
                 )
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/clients/:clientid/unsubscribe/bulk") ->
@@ -336,7 +340,8 @@ schema("/clients/:clientid/unsubscribe/bulk") ->
                 404 => emqx_dashboard_swagger:error_codes(
                     ['CLIENTID_NOT_FOUND'], <<"Client ID not found">>
                 )
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/clients/:clientid/keepalive") ->

apps/emqx_management/src/emqx_mgmt_api_publish.erl

@@ -62,7 +62,8 @@ schema("/publish") ->
                 ?PARTIALLY_OK => hoconsc:mk(hoconsc:ref(?MODULE, publish_error)),
                 ?BAD_REQUEST => hoconsc:mk(hoconsc:ref(?MODULE, bad_request)),
                 ?DISPATCH_ERROR => hoconsc:mk(hoconsc:ref(?MODULE, publish_error))
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     };
 schema("/publish/bulk") ->
@@ -82,7 +83,8 @@ schema("/publish/bulk") ->
                 ?DISPATCH_ERROR => hoconsc:mk(
                     hoconsc:array(hoconsc:ref(?MODULE, publish_error)), #{}
                 )
-            }
+            },
+            log_meta => emqx_dashboard_audit:importance(low)
         }
     }.
 

changes/ee/fix-13963.en.md

@@ -0,0 +1,7 @@
+Fixed below bugs of the Audit Log feature:
+
+- The Audit log feature cannot be used with the SSO feature
+
+  Previously, the Audit log feature could not handle SSO events and each event would throw an exception.
+  
+- Illegal access (for example, a `GET` request to a `POST`-only endpoints) not be logged.

mix.exs

@@ -242,7 +242,7 @@ defmodule EMQXUmbrella.MixProject do
   def common_dep(:rfc3339), do: {:rfc3339, github: "emqx/rfc3339", tag: "0.2.3", override: true}
 
   def common_dep(:minirest),
-    do: {:minirest, github: "emqx/minirest", tag: "1.4.3", override: true}
+    do: {:minirest, github: "emqx/minirest", tag: "1.4.4", override: true}
 
   # maybe forbid to fetch quicer
   def common_dep(:emqtt),

rebar.config

@@ -86,7 +86,7 @@
     {ekka, {git, "https://github.com/emqx/ekka", {tag, "0.19.6"}}},
     {gen_rpc, {git, "https://github.com/emqx/gen_rpc", {tag, "3.4.1"}}},
     {grpc, {git, "https://github.com/emqx/grpc-erl", {tag, "0.6.12"}}},
-    {minirest, {git, "https://github.com/emqx/minirest", {tag, "1.4.3"}}},
+    {minirest, {git, "https://github.com/emqx/minirest", {tag, "1.4.4"}}},
     {ecpool, {git, "https://github.com/emqx/ecpool", {tag, "0.5.10"}}},
     {replayq, {git, "https://github.com/emqx/replayq.git", {tag, "0.3.8"}}},
     {pbkdf2, {git, "https://github.com/emqx/erlang-pbkdf2.git", {tag, "2.0.4"}}},