Skip to content

Commit

Permalink
Merge pull request #180 from emqx/0915-do-not-log-tls-at-error-level
Browse files Browse the repository at this point in the history 
0915 do not log tls at error level
  • Loading branch information
@zmstone
zmstone authored Sep 15, 2023
2 parents c218f45 + 04e2099 commit e794498
Show file tree
Hide file tree
Showing 4 changed files with 90 additions and 15 deletions.
16 changes: 15 additions & 1 deletion src/esockd.appup.src
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,37 +3,43 @@
{"5.9.7",
[{"5.9.6",
[ {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.5",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.4",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.3",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.2",
[ {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.1",
[ {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.0",
Expand All @@ -46,43 +52,50 @@
, {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {add_module,esockd_generic_limiter}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{<<".*">>, []}
],
[{"5.9.6",
[ {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.5",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.4",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.3",
[ {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.2",
[ {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_transport,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.1",
[ {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
, {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{"5.9.0",
Expand All @@ -95,6 +108,7 @@
, {load_module,esockd_udp,brutal_purge,soft_purge,[]}
, {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
, {delete_module,esockd_generic_limiter}
, {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]}
]
},
{<<".*">>, []}
Expand Down
27 changes: 20 additions & 7 deletions src/esockd_connection_sup.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -265,10 +265,19 @@ connection_crashed(_Pid, Reason, _State) when is_atom(Reason) ->
count_shutdown(Reason);
connection_crashed(_Pid, {shutdown, Reason}, _State) when is_atom(Reason) ->
count_shutdown(Reason);
connection_crashed(Pid, {shutdown, {ssl_error, Reason}}, State) ->
count_shutdown(ssl_error),
log(info, ssl_error, Reason, Pid, State);
connection_crashed(Pid, {shutdown, #{shutdown_count := Key} = Reason}, State) when is_atom(Key) ->
count_shutdown(Key),
log(info, Key, maps:without([shutdown_count], Reason), Pid, State);
connection_crashed(Pid, {shutdown, Reason}, State) ->
report_error(connection_shutdown, Reason, Pid, State);
%% unidentified shutdown, cannot keep a counter of it,
%% ideally we should try to add a 'shutdown_count' filed to the reason.
log(error, connection_shutdown, Reason, Pid, State);
connection_crashed(Pid, Reason, State) ->
report_error(connection_crashed, Reason, Pid, State).
%% unexpected crash, probably deserve a fix
log(error, connection_crashed, Reason, Pid, State).

count_shutdown(Reason) ->
Key = {shutdown_count, Reason},
Expand All @@ -291,7 +300,7 @@ terminate_children(State = #state{curr_connections = Conns, shutdown = Shutdown}
end,
%% Unroll stacked errors and report them
dict:fold(fun(Reason, Pid, _) ->
report_error(connection_shutdown_error, Reason, Pid, State)
log(error, connection_shutdown_error, Reason, Pid, State)
end, ok, EStack).

monitor_children(Conns) ->
Expand Down Expand Up @@ -371,15 +380,19 @@ wait_children(Shutdown, Pids, Sz, TRef, EStack) ->
wait_children(Shutdown, Pids, Sz-1, undefined, EStack)
end.

report_error(Error, Reason, Pid, #state{mfargs = MFA}) ->
SupName = list_to_atom("esockd_connection_sup - " ++ pid_to_list(self())),
ErrorMsg = [{supervisor, SupName},
log(Level, Error, Reason, Pid, #state{mfargs = MFA}) ->
ErrorMsg = [{supervisor, {?MODULE, Pid}},
{errorContext, Error},
{reason, Reason},
{offender, [{pid, Pid},
{name, connection},
{mfargs, MFA}]}],
error_logger:error_report(supervisor_report, ErrorMsg).
case Level of
info ->
error_logger:info_report(supervisor_report, ErrorMsg);
error ->
error_logger:error_report(supervisor_report, ErrorMsg)
end.

get_module({M, _F, _A}) -> M;
get_module({M, _F}) -> M;
Expand Down
2 changes: 2 additions & 0 deletions test/echo_server.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,8 @@ loop(Transport, Sock) ->
%%io:format("RECV from ~s: ~s~n", [esockd:format(Peername), Data]),
Transport:send(Sock, Data),
loop(Transport, Sock);
{shutdown, Reason} ->
exit({shutdown, Reason});
{error, Reason} ->
exit({shutdown, Reason})
end.
Expand Down
60 changes: 53 additions & 7 deletions test/esockd_connection_sup_SUITE.erl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,20 +24,56 @@
all() -> esockd_ct:all(?MODULE).

t_start_connection(_) ->
ok = meck:new(esockd_transport, [non_strict, passthrough, no_history]),
ok = meck:expect(esockd_transport, peername, fun(_Sock) -> {ok, {{127,0,0,1}, 3456}} end),
ok = meck:expect(esockd_transport, wait, fun(Sock) -> {ok, Sock} end),
ok = meck:expect(esockd_transport, recv, fun(_Sock, 0) -> {ok, <<"Hi">>} end),
ok = meck:expect(esockd_transport, send, fun(_Sock, _Data) -> ok end),
ok = meck:expect(esockd_transport, controlling_process, fun(_Sock, _ConnPid) -> ok end),
ok = meck:expect(esockd_transport, ready, fun(_ConnPid, _Sock, []) -> ok end),
ok = meck_esockd_transport(fun(_, _) ->
timer:sleep(100),
{ok, <<"Hi">>}
end),
with_conn_sup([{max_connections, 1024}],
fun(ConnSup) ->
{ok, ConnPid} = esockd_connection_sup:start_connection(ConnSup, sock, []),
?assert(is_process_alive(ConnPid))
end),
ok = meck:unload(esockd_transport).

t_shutdown_connection_count(_) ->
RecvFn = fun(_, _) ->
receive
{shutdown, Reason} ->
{shutdown, Reason}
end
end,
ok = meck_esockd_transport(RecvFn),
StartThenShutdown =
fun(ConnSup, Reason) ->
{ok, ConnPid} = esockd_connection_sup:start_connection(ConnSup, sock, []),
?assert(is_process_alive(ConnPid)),
_ = monitor(process, ConnPid),
ConnPid ! {shutdown, Reason},
ConnPid
end,
WaitDown =
fun(ConnPid, ExpectedReason) ->
receive
{'DOWN', _, _, ConnPid, Reason} ->
?assertEqual({shutdown, ExpectedReason}, Reason)
after
1000 ->
error(timeout)
end
end,
with_conn_sup([{max_connections, 1024}],
fun(ConnSup) ->
Reason1 = {ssl_error, bar},
Reason2 = #{shutdown_count => foo, reason => bar},
Pid1 = StartThenShutdown(ConnSup, Reason1),
Pid2 = StartThenShutdown(ConnSup, Reason2),
WaitDown(Pid1, Reason1),
WaitDown(Pid2, Reason2),
Counts = esockd_connection_sup:get_shutdown_count(ConnSup),
?assertEqual([{foo, 1}, {ssl_error, 1}], lists:sort(Counts))
end),
ok = meck:unload(esockd_transport).

t_allow_deny(_) ->
AccessRules = [{allow, "192.168.1.0/24"}],
with_conn_sup([{access_rules, AccessRules}],
Expand Down Expand Up @@ -82,3 +118,13 @@ with_conn_sup(Opts, Fun) ->
Fun(ConnSup),
ok = esockd_connection_sup:stop(ConnSup).

meck_esockd_transport(RecvFn) ->
ok = meck:new(esockd_transport, [non_strict, passthrough, no_history]),
ok = meck:expect(esockd_transport, peername, fun(_Sock) -> {ok, {{127,0,0,1}, 3456}} end),
ok = meck:expect(esockd_transport, wait, fun(Sock) -> {ok, Sock} end),
ok = meck:expect(esockd_transport, recv, RecvFn),
ok = meck:expect(esockd_transport, send, fun(_Sock, _Data) -> ok end),
ok = meck:expect(esockd_transport, controlling_process, fun(_Sock, _ConnPid) -> ok end),
ok = meck:expect(esockd_transport, ready, fun(_ConnPid, _Sock, []) -> ok end),
ok.

0 comments on commit e794498

Please sign in to comment.