yuanbiao
/
emqx
1
0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge pull request #8554 from savonarola/authn-logging 

Add more tracing for authentication
This commit is contained in:
Ilya Averyanov 2022-07-25 17:43:00 +03:00 committed by GitHub
parent 80831a7593 1a236db91b
commit 2f470b8878
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
16 changed files with 182 additions and 112 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
CHANGES-5.0.md
View File

@ -28,7 +28,8 @@
* Improve the dashboard listener startup log, the listener name is no longer spliced with port information,
and the colon(:) is no longer displayed when IP is not specified. [#8480](https://github.com/emqx/emqx/pull/8480)
* Remove `/configs/listeners` API, use `/listeners/` instead. [#8485](https://github.com/emqx/emqx/pull/8485)
* Optimize performance of builtin database operations in processes with long message queue [8439](https://github.com/emqx/emqx/pull/8439)
* Optimize performance of builtin database operations in processes with long message queue [#8439](https://github.com/emqx/emqx/pull/8439)
* Improve authentication tracing. [#8554](https://github.com/emqx/emqx/pull/8554)
# 5.0.3

13
apps/emqx/include/emqx_authentication.hrl
View File

@ -17,6 +17,19 @@
-ifndef(EMQX_AUTHENTICATION_HRL).
-define(EMQX_AUTHENTICATION_HRL, true).
-include_lib("emqx/include/logger.hrl").
-define(AUTHN_TRACE_TAG, "AUTHN").
-define(TRACE_AUTHN_PROVIDER(Msg), ?TRACE_AUTHN_PROVIDER(Msg, #{})).
-define(TRACE_AUTHN_PROVIDER(Msg, Meta), ?TRACE_AUTHN_PROVIDER(debug, Msg, Meta)).
-define(TRACE_AUTHN_PROVIDER(Level, Msg, Meta),
?TRACE_AUTHN(Level, Msg, (Meta)#{provider => ?MODULE})
).
-define(TRACE_AUTHN(Msg, Meta), ?TRACE_AUTHN(debug, Msg, Meta)).
-define(TRACE_AUTHN(Level, Msg, Meta), ?TRACE(Level, ?AUTHN_TRACE_TAG, Msg, Meta)).
%% config root name all auth providers have to agree on.
-define(EMQX_AUTHENTICATION_CONFIG_ROOT_NAME, "authentication").
-define(EMQX_AUTHENTICATION_CONFIG_ROOT_NAME_ATOM, authentication).

18
apps/emqx/include/logger.hrl
View File

@ -42,17 +42,21 @@
-define(TRACE_FILTER, emqx_trace_filter).
-define(TRACE(Tag, Msg, Meta), ?TRACE(debug, Tag, Msg, Meta)).
%% Only evaluate when necessary
%% Always debug the trace events.
-define(TRACE(Tag, Msg, Meta), begin
case persistent_term:get(?TRACE_FILTER, undefined) of
undefined -> ok;
-define(TRACE(Level, Tag, Msg, Meta), begin
case persistent_term:get(?TRACE_FILTER, []) of
[] -> ok;
List -> emqx_trace:log(List, Msg, Meta#{trace_tag => Tag})
%% We can't bind filter list to a variablebecause we pollute the calling scope with it.
%% We also don't want to wrap the macro body in a fun
%% beacause this adds overhead to the happy path.
%% So evaluate `persistent_term:get` twice.
_ -> emqx_trace:log(persistent_term:get(?TRACE_FILTER, []), Msg, (Meta)#{trace_tag => Tag})
end,
?SLOG(
debug,
(emqx_trace_formatter:format_meta(Meta))#{msg => Msg, tag => Tag},
Level,
(emqx_trace_formatter:format_meta_map(Meta))#{msg => Msg, tag => Tag},
#{is_trace => false}
)
end).

31
apps/emqx/src/emqx_authentication.erl
View File

@ -101,6 +101,14 @@
-define(CHAINS_TAB, emqx_authn_chains).
-define(TRACE_RESULT(Label, Result, Reason), begin
?TRACE_AUTHN(Label, #{
result => (Result),
reason => (Reason)
}),
Result
end).
-type chain_name() :: atom().
-type authenticator_id() :: binary().
-type position() :: front | rear | {before, authenticator_id()} | {'after', authenticator_id()}.
@ -216,14 +224,14 @@ when
authenticate(#{enable_authn := false}, _AuthResult) ->
inc_authenticate_metric('authentication.success.anonymous'),
ignore;
?TRACE_RESULT("authentication_result", ignore, enable_authn_false);
authenticate(#{listener := Listener, protocol := Protocol} = Credential, _AuthResult) ->
case get_authenticators(Listener, global_chain(Protocol)) of
{ok, ChainName, Authenticators} ->
case get_enabled(Authenticators) of
[] ->
inc_authenticate_metric('authentication.success.anonymous'),
ignore;
?TRACE_RESULT("authentication_result", ignore, empty_chain);
NAuthenticators ->
Result = do_authenticate(ChainName, NAuthenticators, Credential),
@ -235,11 +243,11 @@ authenticate(#{listener := Listener, protocol := Protocol} = Credential, _AuthRe
_ ->
ok
end,
Result
?TRACE_RESULT("authentication_result", Result, chain_result)
end;
none ->
inc_authenticate_metric('authentication.success.anonymous'),
ignore
?TRACE_RESULT("authentication_result", ignore, no_chain)
end.
get_authenticators(Listener, Global) ->
@ -626,11 +634,11 @@ handle_create_authenticator(Chain, Config, Providers) ->
do_authenticate(_ChainName, [], _) ->
{stop, {error, not_authorized}};
do_authenticate(
ChainName, [#authenticator{id = ID, provider = Provider, state = State} | More], Credential
ChainName, [#authenticator{id = ID} = Authenticator | More], Credential
) ->
MetricsID = metrics_id(ChainName, ID),
emqx_metrics_worker:inc(authn_metrics, MetricsID, total),
try Provider:authenticate(Credential, State) of
try authenticate_with_provider(Authenticator, Credential) of
ignore ->
ok = emqx_metrics_worker:inc(authn_metrics, MetricsID, nomatch),
do_authenticate(ChainName, More, Credential);
@ -651,8 +659,7 @@ do_authenticate(
{stop, Result}
catch
Class:Reason:Stacktrace ->
?SLOG(warning, #{
msg => "unexpected_error_in_authentication",
?TRACE_AUTHN(warning, "authenticator_error", #{
exception => Class,
reason => Reason,
stacktrace => Stacktrace,
@ -662,6 +669,14 @@ do_authenticate(
do_authenticate(ChainName, More, Credential)
end.
authenticate_with_provider(#authenticator{id = ID, provider = Provider, state = State}, Credential) ->
AuthnResult = Provider:authenticate(Credential, State),
?TRACE_AUTHN("authenticator_result", #{
authenticator => ID,
result => AuthnResult
}),
AuthnResult.
reply(Reply, State) ->
{reply, Reply, State}.

15
apps/emqx/src/emqx_trace/emqx_trace.erl
View File

@ -92,15 +92,16 @@ unsubscribe(<<"$SYS/", _/binary>>, _SubOpts) ->
unsubscribe(Topic, SubOpts) ->
?TRACE("UNSUBSCRIBE", "unsubscribe", #{topic => Topic, sub_opts => SubOpts}).
log(List, Msg, Meta0) ->
Meta =
case logger:get_process_metadata() of
undefined -> Meta0;
ProcMeta -> maps:merge(ProcMeta, Meta0)
end,
Log = #{level => debug, meta => Meta, msg => Msg},
log(List, Msg, Meta) ->
Log = #{level => debug, meta => enrich_meta(Meta), msg => Msg},
log_filter(List, Log).
enrich_meta(Meta) ->
case logger:get_process_metadata() of
undefined -> Meta;
ProcMeta -> maps:merge(ProcMeta, Meta)
end.
log_filter([], _Log) ->
ok;
log_filter([{Id, FilterFun, Filter, Name} | Rest], Log0) ->

51
apps/emqx/src/emqx_trace/emqx_trace_formatter.erl
View File

@ -16,7 +16,7 @@
-module(emqx_trace_formatter).
-export([format/2]).
-export([format_meta/1]).
-export([format_meta_map/1]).
%%%-----------------------------------------------------------------
%%% API
@ -31,32 +31,39 @@ format(
ClientId = to_iolist(maps:get(clientid, Meta, "")),
Peername = maps:get(peername, Meta, ""),
MetaBin = format_meta(Meta, PEncode),
[Time, " [", Tag, "] ", ClientId, "@", Peername, " msg: ", Msg, MetaBin, "\n"];
[Time, " [", Tag, "] ", ClientId, "@", Peername, " msg: ", Msg, ", ", MetaBin, "\n"];
format(Event, Config) ->
emqx_logger_textfmt:format(Event, Config).
format_meta(Meta) ->
format_meta_map(Meta) ->
Encode = emqx_trace_handler:payload_encode(),
do_format_meta(Meta, Encode).
format_meta_map(Meta, Encode).
format_meta(Meta0, Encode) ->
Meta1 = #{packet := Packet0, payload := Payload0} = do_format_meta(Meta0, Encode),
Packet = enrich(", packet: ", Packet0),
Payload = enrich(", payload: ", Payload0),
Meta2 = maps:without([msg, clientid, peername, packet, payload, trace_tag], Meta1),
case Meta2 =:= #{} of
true -> [Packet, Payload];
false -> [Packet, ", ", map_to_iolist(Meta2), Payload]
format_meta_map(Meta, Encode) ->
format_meta_map(Meta, Encode, [{packet, fun format_packet/2}, {payload, fun format_payload/2}]).
format_meta_map(Meta, _Encode, []) ->
Meta;
format_meta_map(Meta, Encode, [{Name, FormatFun} | Rest]) ->
case Meta of
#{Name := Value} ->
NewMeta = Meta#{Name => FormatFun(Value, Encode)},
format_meta_map(NewMeta, Encode, Rest);
#{} ->
format_meta_map(Meta, Encode, Rest)
end.
enrich(_, "") -> "";
enrich(Key, IoData) -> [Key, IoData].
format_meta(Meta0, Encode) ->
Meta1 = maps:without([msg, clientid, peername, trace_tag], Meta0),
Meta2 = format_meta_map(Meta1, Encode),
kvs_to_iolist(lists:sort(fun compare_meta_kvs/2, maps:to_list(Meta2))).
do_format_meta(Meta, Encode) ->
Meta#{
packet => format_packet(maps:get(packet, Meta, undefined), Encode),
payload => format_payload(maps:get(payload, Meta, undefined), Encode)
}.
%% packet always goes first; payload always goes last
compare_meta_kvs(KV1, KV2) -> weight(KV1) =< weight(KV2).
weight({packet, _}) -> {0, packet};
weight({payload, _}) -> {2, payload};
weight({K, _}) -> {1, K}.
format_packet(undefined, _) -> "";
format_packet(Packet, Encode) -> emqx_packet:format(Packet, Encode).
@ -69,14 +76,14 @@ format_payload(_, hidden) -> "******".
to_iolist(Atom) when is_atom(Atom) -> atom_to_list(Atom);
to_iolist(Int) when is_integer(Int) -> integer_to_list(Int);
to_iolist(Float) when is_float(Float) -> float_to_list(Float, [{decimals, 2}]);
to_iolist(SubMap) when is_map(SubMap) -> ["[", map_to_iolist(SubMap), "]"];
to_iolist(SubMap) when is_map(SubMap) -> ["[", kvs_to_iolist(maps:to_list(SubMap)), "]"];
to_iolist(Char) -> emqx_logger_textfmt:try_format_unicode(Char).
map_to_iolist(Map) ->
kvs_to_iolist(KVs) ->
lists:join(
", ",
lists:map(
fun({K, V}) -> [to_iolist(K), ": ", to_iolist(V)] end,
maps:to_list(Map)
KVs
)
).

4
apps/emqx_authn/include/emqx_authn.hrl
View File

@ -36,6 +36,6 @@
-type authenticator_id() :: binary().
-endif.
-define(RESOURCE_GROUP, <<"emqx_authn">>).
-endif.

16
apps/emqx_authn/src/emqx_authn_utils.erl
View File

@ -33,7 +33,8 @@
bin/1,
ensure_apps_started/1,
cleanup_resources/0,
make_resource_id/1
make_resource_id/1,
without_password/1
]).
-define(AUTHN_PLACEHOLDERS, [
@ -199,10 +200,23 @@ make_resource_id(Name) ->
NameBin = bin(Name),
emqx_resource:generate_id(NameBin).
without_password(Credential) ->
without_password(Credential, [password, <<"password">>]).
%%--------------------------------------------------------------------
%% Internal functions
%%--------------------------------------------------------------------
without_password(Credential, []) ->
Credential;
without_password(Credential, [Name | Rest]) ->
case maps:is_key(Name, Credential) of
true ->
without_password(Credential#{Name => <<"[password]">>}, Rest);
false ->
without_password(Credential, Rest)
end.
handle_var({var, Name}, undefined) ->
error({cannot_get_variable, Name});
handle_var({var, <<"peerhost">>}, PeerHost) ->

10
apps/emqx_authn/src/enhanced_authn/emqx_enhanced_authn_scram_mnesia.erl
View File

@ -331,7 +331,10 @@ check_client_first_message(Bin, _Cache, #{iteration_count := IterationCount} = S
{continue, ServerFirstMessage, Cache};
ignore ->
ignore;
{error, _Reason} ->
{error, Reason} ->
?TRACE_AUTHN_PROVIDER("check_client_first_message_error", #{
reason => Reason
}),
{error, not_authorized}
end.
@ -344,7 +347,10 @@ check_client_final_message(Bin, #{is_superuser := IsSuperuser} = Cache, #{algori
of
{ok, ServerFinalMessage} ->
{ok, #{is_superuser => IsSuperuser}, ServerFinalMessage};
{error, _Reason} ->
{error, Reason} ->
?TRACE_AUTHN_PROVIDER("check_client_final_message_error", #{
reason => Reason
}),
{error, not_authorized}
end.

68
apps/emqx_authn/src/simple_authn/emqx_authn_http.erl
View File

@ -188,23 +188,22 @@ authenticate(
} = State
) ->
Request = generate_request(Credential, State),
case emqx_resource:query(ResourceId, {Method, Request, RequestTimeout}) of
Response = emqx_resource:query(ResourceId, {Method, Request, RequestTimeout}),
?TRACE_AUTHN_PROVIDER("http_response", #{
request => request_for_log(Credential, State),
response => response_for_log(Response),
resource => ResourceId
}),
case Response of
{ok, 204, _Headers} ->
{ok, #{is_superuser => false}};
{ok, 200, Headers, Body} ->
handle_response(Headers, Body);
{ok, _StatusCode, _Headers} = Response ->
log_response(ResourceId, Response),
ignore;
{ok, _StatusCode, _Headers, _Body} = Response ->
log_response(ResourceId, Response),
ignore;
{error, Reason} ->
?SLOG(error, #{
msg => "http_server_query_failed",
resource => ResourceId,
reason => Reason
}),
{error, _Reason} ->
ignore
end.
@ -296,7 +295,8 @@ parse_config(
cow_qs:parse_qs(to_bin(Query))
),
body_template => emqx_authn_utils:parse_deep(maps:get(body, Config, #{})),
request_timeout => RequestTimeout
request_timeout => RequestTimeout,
url => RawUrl
},
{Config#{base_url => BaseUrl, pool_type => random}, State}.
@ -379,11 +379,6 @@ parse_body(<<"application/x-www-form-urlencoded", _/binary>>, Body) ->
parse_body(ContentType, _) ->
{error, {unsupported_content_type, ContentType}}.
may_append_body(Output, {ok, _, _, Body}) ->
Output#{body => Body};
may_append_body(Output, {ok, _, _}) ->
Output.
uri_encode(T) ->
emqx_http_lib:uri_encode(to_list(T)).
@ -391,26 +386,33 @@ encode_path(Path) ->
Parts = string:split(Path, "/", all),
lists:flatten(["/" ++ Part || Part <- lists:map(fun uri_encode/1, Parts)]).
log_response(ResourceId, Other) ->
Output = may_append_body(#{resource => ResourceId}, Other),
case erlang:element(2, Other) of
Code5xx when Code5xx >= 500 andalso Code5xx < 600 ->
?SLOG(error, Output#{
msg => "http_server_error",
code => Code5xx
});
Code4xx when Code4xx >= 400 andalso Code4xx < 500 ->
?SLOG(warning, Output#{
msg => "refused_by_http_server",
code => Code4xx
});
OtherCode ->
?SLOG(error, Output#{
msg => "undesired_response_code",
code => OtherCode
})
request_for_log(Credential, #{url := Url} = State) ->
SafeCredential = emqx_authn_utils:without_password(Credential),
case generate_request(SafeCredential, State) of
{PathQuery, Headers} ->
#{
method => post,
base_url => Url,
path_query => PathQuery,
headers => Headers
};
{PathQuery, Headers, Body} ->
#{
method => post,
base_url => Url,
path_query => PathQuery,
headers => Headers,
mody => Body
}
end.
response_for_log({ok, StatusCode, Headers}) ->
#{status => StatusCode, headers => Headers};
response_for_log({ok, StatusCode, Headers, Body}) ->
#{status => StatusCode, headers => Headers, body => Body};
response_for_log({error, Error}) ->
#{error => Error}.
to_list(A) when is_atom(A) ->
atom_to_list(A);
to_list(B) when is_binary(B) ->

34
apps/emqx_authn/src/simple_authn/emqx_authn_jwt.erl
View File

@ -227,8 +227,7 @@ authenticate(
) ->
case emqx_resource:query(ResourceId, get_jwks) of
{error, Reason} ->
?SLOG(error, #{
msg => "get_jwks_failed",
?TRACE_AUTHN_PROVIDER(error, "get_jwks_failed", #{
resource => ResourceId,
reason => Reason
}),
@ -350,10 +349,17 @@ verify(undefined, _, _, _) ->
ignore;
verify(JWT, JWKs, VerifyClaims, AclClaimName) ->
case do_verify(JWT, JWKs, VerifyClaims) of
{ok, Extra} -> {ok, acl(Extra, AclClaimName)};
{error, {missing_claim, _}} -> {error, bad_username_or_password};
{error, invalid_signature} -> ignore;
{error, {claims, _}} -> {error, bad_username_or_password}
{ok, Extra} ->
{ok, acl(Extra, AclClaimName)};
{error, {missing_claim, Claim}} ->
?TRACE_AUTHN_PROVIDER("missing_jwt_claim", #{jwt => JWT, claim => Claim}),
{error, bad_username_or_password};
{error, invalid_signature} ->
?TRACE_AUTHN_PROVIDER("invalid_jwt_signature", #{jwks => JWKs, jwt => JWT}),
ignore;
{error, {claims, Claims}} ->
?TRACE_AUTHN_PROVIDER("invalid_jwt_claims", #{jwt => JWT, claims => Claims}),
{error, bad_username_or_password}
end.
acl(Claims, AclClaimName) ->
@ -371,11 +377,11 @@ acl(Claims, AclClaimName) ->
end,
maps:merge(emqx_authn_utils:is_superuser(Claims), Acl).
do_verify(_JWS, [], _VerifyClaims) ->
do_verify(_JWT, [], _VerifyClaims) ->
{error, invalid_signature};
do_verify(JWS, [JWK | More], VerifyClaims) ->
try jose_jws:verify(JWK, JWS) of
{true, Payload, _JWS} ->
do_verify(JWT, [JWK | More], VerifyClaims) ->
try jose_jws:verify(JWK, JWT) of
{true, Payload, _JWT} ->
Claims0 = emqx_json:decode(Payload, [return_maps]),
Claims = try_convert_to_int(Claims0, [<<"exp">>, <<"iat">>, <<"nbf">>]),
case verify_claims(Claims, VerifyClaims) of
@ -385,11 +391,11 @@ do_verify(JWS, [JWK | More], VerifyClaims) ->
{error, Reason}
end;
{false, _, _} ->
do_verify(JWS, More, VerifyClaims)
do_verify(JWT, More, VerifyClaims)
catch
_:_Reason ->
?TRACE("JWT", "authn_jwt_invalid_signature", #{jwk => JWK, jws => JWS}),
{error, invalid_signature}
_:Reason ->
?TRACE_AUTHN_PROVIDER("jwt_verify_error", #{jwk => JWK, jwt => JWT, reason => Reason}),
do_verify(JWT, More, VerifyClaims)
end.
verify_claims(Claims, VerifyClaims0) ->

8
apps/emqx_authn/src/simple_authn/emqx_authn_mnesia.erl
View File

@ -17,6 +17,7 @@
-module(emqx_authn_mnesia).
-include("emqx_authn.hrl").
-include_lib("emqx/include/logger.hrl").
-include_lib("stdlib/include/ms_transform.hrl").
-include_lib("hocon/include/hoconsc.hrl").
@ -158,6 +159,7 @@ authenticate(
UserID = get_user_identity(Credential, Type),
case mnesia:dirty_read(?TAB, {UserGroup, UserID}) of
[] ->
?TRACE_AUTHN_PROVIDER("user_not_found"),
ignore;
[#user_info{password_hash = PasswordHash, salt = Salt, is_superuser = IsSuperuser}] ->
case
@ -165,8 +167,10 @@ authenticate(
Algorithm, Salt, PasswordHash, Password
)
of
true -> {ok, #{is_superuser => IsSuperuser}};
false -> {error, bad_username_or_password}
true ->
{ok, #{is_superuser => IsSuperuser}};
false ->
{error, bad_username_or_password}
end
end.

7
apps/emqx_authn/src/simple_authn/emqx_authn_mongodb.erl
View File

@ -167,8 +167,7 @@ authenticate(
undefined ->
ignore;
{error, Reason} ->
?SLOG(error, #{
msg => "mongodb_query_failed",
?TRACE_AUTHN_PROVIDER(error, "mongodb_query_failed", #{
resource => ResourceId,
collection => Collection,
filter => Filter,
@ -180,11 +179,11 @@ authenticate(
ok ->
{ok, is_superuser(Doc, State)};
{error, {cannot_find_password_hash_field, PasswordHashField}} ->
?SLOG(error, #{
msg => "cannot_find_password_hash_field",
?TRACE_AUTHN_PROVIDER(error, "cannot_find_password_hash_field", #{
resource => ResourceId,
collection => Collection,
filter => Filter,
document => Doc,
password_hash_field => PasswordHashField
}),
ignore;

3
apps/emqx_authn/src/simple_authn/emqx_authn_mysql.erl
View File

@ -130,8 +130,7 @@ authenticate(
{error, Reason}
end;
{error, Reason} ->
?SLOG(error, #{
msg => "mysql_query_failed",
?TRACE_AUTHN_PROVIDER(error, "mysql_query_failed", #{
resource => ResourceId,
tmpl_token => TmplToken,
params => Params,

3
apps/emqx_authn/src/simple_authn/emqx_authn_pgsql.erl
View File

@ -133,8 +133,7 @@ authenticate(
{error, Reason}
end;
{error, Reason} ->
?SLOG(error, #{
msg => "postgresql_query_failed",
?TRACE_AUTHN_PROVIDER(error, "postgresql_query_failed", #{
resource => ResourceId,
params => Params,
reason => Reason

8
apps/emqx_authn/src/simple_authn/emqx_authn_redis.erl
View File

@ -128,13 +128,14 @@ authenticate(#{auth_method := _}, _) ->
authenticate(
#{password := Password} = Credential,
#{
cmd := {Command, KeyTemplate, Fields},
cmd := {CommandName, KeyTemplate, Fields},
resource_id := ResourceId,
password_hash_algorithm := Algorithm
}
) ->
NKey = emqx_authn_utils:render_str(KeyTemplate, Credential),
case emqx_resource:query(ResourceId, {cmd, [Command, NKey | Fields]}) of
Command = [CommandName, NKey | Fields],
case emqx_resource:query(ResourceId, {cmd, Command}) of
{ok, []} ->
ignore;
{ok, Values} ->
@ -150,8 +151,7 @@ authenticate(
{error, Reason}
end;
{error, Reason} ->
?SLOG(error, #{
msg => "redis_query_failed",
?TRACE_AUTHN_PROVIDER(error, "redis_query_failed", #{
resource => ResourceId,
cmd => Command,
keys => NKey,