Merge pull request #177 from emqx/log-error-when-recv-proxy-info-timeout

Log error when recv proxy info timeout

src/esockd.app.src

@@ -1,7 +1,7 @@
 {application, esockd,
  [{description, "General Non-blocking TCP/SSL and UDP/DTLS Server"},
   {id, "esockd"},
-  {vsn, "5.8.9"},
+  {vsn, "5.8.10"},
   {modules, []},
   {registered, []},
   {applications, [kernel, stdlib, sasl, ssl]},

src/esockd.appup.src

@@ -1,30 +1,30 @@
 %%-*- mode: erlang; -*-
 
-{"5.8.9",
-  [{"5.8.8",
-    [{load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
-     {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
-    ]},
-   {<<"5\\.8\\.[6-7]">>,
-    [{load_module,esockd_transport,brutal_purge,soft_purge,[]},
+{"5.8.10",
+  [{<<"5\\.8\\.[6-9]">>,
+    [{add_module,esockd_utils},
+     {load_module,esockd_transport,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
     ]},
    {<<"5\\.8\\.[4-5]">>,
-    [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
+    [{add_module,esockd_utils},
+     {load_module,esockd_udp,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
      {load_module,esockd_transport,brutal_purge,soft_purge,[]}
     ]},
    {"5.8.3",
-    [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
+    [{add_module,esockd_utils},
+     {load_module,esockd_udp,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
-     {load_module, esockd_limiter, brutal_purge, soft_purge, []},
+     {load_module,esockd_limiter, brutal_purge, soft_purge, []},
      {load_module,esockd_transport,brutal_purge,soft_purge,[]}
     ]},
    {<<"5\\.8\\.[0-2]">>,
-    [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
+    [{add_module,esockd_utils},
+     {load_module,esockd_udp,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
      {load_module,esockd_connection_sup,brutal_purge,soft_purge,[]},
@@ -35,27 +35,26 @@
     ]},
    {<<".*">>, []}
   ],
-  [{"5.8.8",
-    [{load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
-     {load_module,esockd_acceptor,brutal_purge,soft_purge,[]}
-    ]},
-   {<<"5\\.8\\.[6-7]">>,
+  [{<<"5\\.8\\.[6-9]">>,
     [{load_module,esockd_transport,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
-     {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]}
+     {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
+     {delete_module,esockd_utils}
     ]},
    {<<"5\\.8\\.[4-5]">>,
     [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
-     {load_module,esockd_transport,brutal_purge,soft_purge,[]}
+     {load_module,esockd_transport,brutal_purge,soft_purge,[]},
+     {delete_module,esockd_utils}
     ]},
    {"5.8.3",
     [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
      {load_module,esockd_acceptor,brutal_purge,soft_purge,[]},
      {load_module,esockd_proxy_protocol,brutal_purge,soft_purge,[]},
-     {load_module, esockd_limiter, brutal_purge, soft_purge, []},
-     {load_module,esockd_transport,brutal_purge,soft_purge,[]}
+     {load_module,esockd_limiter, brutal_purge, soft_purge, []},
+     {load_module,esockd_transport,brutal_purge,soft_purge,[]},
+     {delete_module,esockd_utils}
     ]},
    {<<"5\\.8\\.[0-2]">>,
     [{load_module,esockd_udp,brutal_purge,soft_purge,[]},
@@ -65,7 +64,8 @@
      {load_module,esockd_dtls_listener,brutal_purge,soft_purge,[]},
      {load_module,esockd_transport,brutal_purge,soft_purge,[]},
      {load_module,esockd_peercert,brutal_purge,soft_purge,[]},
-     {load_module,esockd,brutal_purge,soft_purge,[]}
+     {load_module,esockd,brutal_purge,soft_purge,[]},
+     {delete_module,esockd_utils}
     ]},
    {<<".*">>, []}
   ]

src/esockd_acceptor.erl

@@ -159,7 +159,7 @@ accepting(info, {inet_async, LSock, Ref, {error, Reason}},
           State = #state{lsock = LSock, sockname = Sockname, accept_ref = Ref})
     when Reason =:= emfile; Reason =:= enfile ->
     error_logger:error_msg("Accept error on ~s: ~s",
-                           [esockd:format(Sockname), explain_posix(Reason)]),
+                           [esockd:format(Sockname), esockd_utils:explain_posix(Reason)]),
     {next_state, suspending, State, 1000};
 
 accepting(info, {inet_async, LSock, Ref, {error, Reason}},
@@ -194,8 +194,3 @@ rate_limit(State = #state{conn_limiter = Limiter}) ->
 
 eval_tune_socket_fun({Fun, Args1}, Sock) ->
     apply(Fun, [Sock|Args1]).
-
-explain_posix(emfile) ->
-    "EMFILE (Too many open files)";
-explain_posix(enfile) ->
-    "ENFILE (File table overflow)".

src/esockd_proxy_protocol.erl

@@ -25,6 +25,16 @@
 -export([parse_v1/2, parse_v2/4, parse_pp2_tlv/2, parse_pp2_ssl/1]).
 -endif.
 
+-define(ERR_MSG_IN_PP_MODE, "The listener ~s is working in proxy protocol mode, but ").
+
+-define(LOG(LEVEL, FROMAT, ARGS), logger:log(LEVEL, "[~s] " ++ FROMAT, [?MODULE | ARGS])).
+-define(LOG_PP_ERROR(FROMAT, ARGS, Sock),
+        ?LOG(error, ?ERR_MSG_IN_PP_MODE ++ FROMAT, [
+            case Transport:sockname(Sock) of
+                {ok, SockName} -> esockd:format(SockName);
+                _ -> unknown
+            end | explain_posix_errors(ARGS)])).
+
 %% Protocol Command
 -define(LOCAL, 16#0).
 -define(PROXY, 16#1).
@@ -83,19 +93,23 @@ recv(Transport, Sock, Timeout) ->
                     Transport:setopts(Sock, OriginOpts),
                     parse_v2(Cmd, Trans, ProxyInfo, #proxy_socket{inet = inet_family(AF), socket = Sock});
                 {error, Reason} ->
-                    {error, {recv_proxy_info_error, Reason}}
+                    ?LOG_PP_ERROR("got an error while receiving proxy_protocol header, reason=~p", [Reason], Sock),
+                    {error, recv_proxy_info_error}
             end;
         {tcp_error, _Sock, Reason} ->
-            {error, {recv_proxy_info_error, Reason}};
+            ?LOG_PP_ERROR("got an error while waiting for proxy_protocol header, reason=~p", [Reason], Sock),
+            {error, recv_proxy_info_error};
         {tcp_closed, _Sock} ->
             %% Socket closed before any data is received.
             %% Here we return an atom here to avoid error level logging.
             %% See the from the connection_crashed function in esockd_connection_sup.erl.
             {error, proxy_proto_close};
         {_, _Sock, ProxyInfo} ->
-            {error, {invalid_proxy_info, ProxyInfo}}
+            ?LOG_PP_ERROR("received invalid proxy_protocol header, raw_bytes=~p", [ProxyInfo], Sock),
+            {error, invalid_proxy_info}
     after
         Timeout ->
+            ?LOG_PP_ERROR("timed out while waiting for proxy_protocol header", [], Sock),
             {error, proxy_proto_timeout}
     end.
 
@@ -211,3 +225,5 @@ inet_family(?UNIX)   -> unix.
 bool(1) -> true;
 bool(_) -> false.
 
+explain_posix_errors(Args) ->
+    [esockd_utils:explain_posix(A) || A <- Args].

src/esockd_transport.erl

@@ -27,7 +27,7 @@
 -export([close/1, fast_close/1]).
 -export([getopts/2, setopts/2, getstat/2]).
 -export([sockname/1, peername/1, shutdown/2]).
--export([peercert/1, peer_cert_subject/1, peer_cert_common_name/1]).
+-export([peercert/1, peer_cert_subject/1, peer_cert_common_name/1, peersni/1]).
 -export([ensure_ok_or_exit/2]).
 -export([gc/1]).
 
@@ -331,6 +331,22 @@ peer_cert_common_name(#proxy_socket{pp2_additional_info = AdditionalInfo}) ->
     proplists:get_value(pp2_ssl_cn,
                         proplists:get_value(pp2_ssl, AdditionalInfo, [])).
 
+-spec(peersni(socket()) -> undefined | binary()).
+peersni(Sock) when is_port(Sock) ->
+    undefined;
+peersni(#ssl_socket{ssl = SslSock}) ->
+    case ssl:connection_information(SslSock, [sni_hostname]) of
+        {ok, [{sni_hostname, SNI}]} when is_list(SNI) -> list_to_binary(SNI);
+        %% If the client does not support SNI extensions,
+        %% an empty list will be returned here
+        %%
+        %% see: https://github.com/erlang/otp/blob/e6ef9cb92499377c24d818376bfd60cbbcf68e60/lib/ssl/src/ssl.erl#L927-L935
+        {ok, []} -> undefined;
+        {error, _Reason} -> undefined
+    end;
+peersni(#proxy_socket{pp2_additional_info = AdditionalInfo}) ->
+    proplists:get_value(pp2_authority, AdditionalInfo, undefined).
+
 %% @doc Shutdown socket
 -spec(shutdown(socket(), How) -> ok | {error, inet:posix()} when
     How :: read | write | read_write).
@@ -349,10 +365,6 @@ ssl_upgrade_fun(SslOpts) ->
     {fun ?MODULE:ssl_upgrade/3, [SslOpts2, #{timeout => Timeout,
                                              gc_after_handshake => GCAfterHandshake}]}.
 
-%% NOTE: The first clause of the function `ssl_upgrade` (with an integer parameter
-%% `Timeout`) will be called by the running process after relup. So don't delete it.
-ssl_upgrade(Sock, SslOpts1, Timeout) when is_integer(Timeout) ->
-    ssl_upgrade(Sock, SslOpts1, #{timeout => Timeout, gc_after_handshake => false});
 ssl_upgrade(Sock, SslOpts1, #{timeout := Timeout,
                               gc_after_handshake := GCAfterHandshake}) ->
     try do_ssl_handshake(Sock, SslOpts1, Timeout) of
@@ -434,7 +446,7 @@ ensure_ok_or_exit(Fun, Args = [Sock|_]) when is_atom(Fun), is_list(Args) ->
     end.
 
 gc(Sock) when is_port(Sock) ->
-case erlang:port_info(Sock, connected) of
+    case erlang:port_info(Sock, connected) of
         {connected, Pid} ->
             erlang:garbage_collect(Pid),
             ok;

src/esockd_utils.erl

@@ -0,0 +1,52 @@
+%%--------------------------------------------------------------------
+%% Copyright (c) 2020 EMQ Technologies Co., Ltd. All Rights Reserved.
+%%
+%% Licensed under the Apache License, Version 2.0 (the "License");
+%% you may not use this file except in compliance with the License.
+%% You may obtain a copy of the License at
+%%
+%%     http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing, software
+%% distributed under the License is distributed on an "AS IS" BASIS,
+%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+%% See the License for the specific language governing permissions and
+%% limitations under the License.
+%%--------------------------------------------------------------------
+-module(esockd_utils).
+
+-export([explain_posix/1]).
+
+explain_posix(eacces) -> "EACCES (Permission denied)";
+explain_posix(eagain) -> "EAGAIN (Resource temporarily unavailable)";
+explain_posix(ebadf) -> "EBADF (Bad file number)";
+explain_posix(ebusy) -> "EBUSY (File busy)";
+explain_posix(edquot) -> "EDQUOT (Disk quota exceeded)";
+explain_posix(eexist) -> "EEXIST (File already exists)";
+explain_posix(efault) -> "EFAULT (Bad address in system call argument)";
+explain_posix(efbig) -> "EFBIG (File too large)";
+explain_posix(eintr) -> "EINTR (Interrupted system call)";
+explain_posix(einval) -> "EINVAL (Invalid argument argument file/socket)";
+explain_posix(eio) -> "EIO (I/O error)";
+explain_posix(eisdir) -> "EISDIR (Illegal operation on a directory)";
+explain_posix(eloop) -> "ELOOP (Too many levels of symbolic links)";
+explain_posix(emfile) -> "EMFILE (Too many open files)";
+explain_posix(emlink) -> "EMLINK (Too many links)";
+explain_posix(enametoolong) -> "ENAMETOOLONG (Filename too long)";
+explain_posix(enfile) -> "ENFILE (File table overflow)";
+explain_posix(enodev) -> "ENODEV (No such device)";
+explain_posix(enoent) -> "ENOENT (No such file or directory)";
+explain_posix(enomem) -> "ENOMEM (Not enough memory)";
+explain_posix(enospc) -> "ENOSPC (No space left on device)";
+explain_posix(enotblk) -> "ENOTBLK (Block device required)";
+explain_posix(enotdir) -> "ENOTDIR (Not a directory)";
+explain_posix(enotsup) -> "ENOTSUP (Operation not supported)";
+explain_posix(enxio) -> "ENXIO (No such device or address)";
+explain_posix(eperm) -> "EPERM (Not owner)";
+explain_posix(epipe) -> "EPIPE (Broken pipe)";
+explain_posix(erofs) -> "EROFS (Read-only file system)";
+explain_posix(espipe) -> "ESPIPE (Invalid seek)";
+explain_posix(esrch) -> "ESRCH (No such process)";
+explain_posix(estale) -> "ESTALE (Stale remote file handle)";
+explain_posix(exdev) -> "EXDEV (Cross-domain link)";
+explain_posix(NotPosix) -> NotPosix.

test/esockd_proxy_protocol_SUITE.erl

@@ -57,50 +57,61 @@ is_t_recv(TestCase) ->
 %%--------------------------------------------------------------------
 
 t_recv_ppv1(_) ->
-    ok = send_proxy_info(<<"PROXY TCP4 192.168.1.1 192.168.1.2 80 81\r\n">>),
+    Sock = sock(),
+    ok = send_proxy_info(Sock, <<"PROXY TCP4 192.168.1.1 192.168.1.2 80 81\r\n">>),
     {ok, #proxy_socket{src_addr = {192,168,1,1}, src_port = 80,
                        dst_addr = {192,168,1,2}, dst_port = 81,
-                       inet = inet4}} = recv_proxy_info().
+                       inet = inet4}} = recv_proxy_info(Sock).
 
 t_recv_ppv1_unknown(_) ->
-    ok = send_proxy_info(<<"PROXY UNKNOWN\r\n">>),
-    {ok, sock} = recv_proxy_info().
+    Sock = sock(),
+    ok = send_proxy_info(Sock, <<"PROXY UNKNOWN\r\n">>),
+    {ok, Sock} = recv_proxy_info(Sock).
 
 t_recv_ppv2(_) ->
-    ok = send_proxy_info(<<13,10>>),
+    Sock = sock(),
+    ok = send_proxy_info(Sock, <<13,10>>),
     ok = meck:expect(esockd_transport, recv,
-                     fun(sock, 14, _) -> {ok, <<13,10,0,13,10,81,85,73,84,10,33,17,0,12>>};
-                        (sock, 12, _) -> {ok, <<127,50,210,1,210,21,16,142,250,32,1,181>>}
+                     fun(S, 14, _) when S =:= Sock ->
+                            {ok, <<13,10,0,13,10,81,85,73,84,10,33,17,0,12>>};
+                        (S, 12, _) when S =:= Sock ->
+                            {ok, <<127,50,210,1,210,21,16,142,250,32,1,181>>}
                      end),
     {ok, #proxy_socket{inet = inet4,
                        src_addr = {127,50,210,1},
                        dst_addr = {210,21,16,142},
                        src_port = 64032,
-                       dst_port = 437}} = recv_proxy_info().
+                       dst_port = 437}} = recv_proxy_info(Sock).
 
 t_recv_pp_invalid(_) ->
-    send_proxy_info(ProxyInfo = <<"Invalid PROXY\r\n">>),
-    {error, {invalid_proxy_info, ProxyInfo}} = recv_proxy_info().
+    Sock = sock(),
+    send_proxy_info(Sock, <<"Invalid PROXY\r\n">>),
+    {error, invalid_proxy_info} = recv_proxy_info(Sock).
 
 t_recv_socket_error(_) ->
+    Sock = sock(),
     Reason = closed,
-    ok = send_socket_error(Reason),
-    ?assertEqual({error, {recv_proxy_info_error, Reason}}, recv_proxy_info()),
+    ok = send_socket_error(Sock, Reason),
+    ?assertEqual({error, recv_proxy_info_error}, recv_proxy_info(Sock)),
 
-    ok = send_socket_closed(),
-    ?assertEqual({error, proxy_proto_close}, recv_proxy_info()).
+    ok = send_socket_closed(Sock),
+    ?assertEqual({error, proxy_proto_close}, recv_proxy_info(Sock)).
 
-send_proxy_info(ProxyInfo) ->
-    self() ! {tcp, sock, ProxyInfo}, ok.
+send_proxy_info(Sock, ProxyInfo) ->
+    self() ! {tcp, Sock, ProxyInfo}, ok.
 
-send_socket_error(Reason) ->
-    self() ! {tcp_error, sock, Reason}, ok.
+send_socket_error(Sock, Reason) ->
+    self() ! {tcp_error, Sock, Reason}, ok.
 
-send_socket_closed() ->
-    self() ! {tcp_closed, sock}, ok.
+send_socket_closed(Sock) ->
+    self() ! {tcp_closed, Sock}, ok.
 
-recv_proxy_info() ->
-    esockd_proxy_protocol:recv(esockd_transport, sock, 1000).
+recv_proxy_info(Sock) ->
+    esockd_proxy_protocol:recv(esockd_transport, Sock, 1000).
+
+sock() ->
+    {ok, Sock} = gen_tcp:listen(0, [{reuseaddr, true}, list]),
+    Sock.
 
 %%--------------------------------------------------------------------
 %% Test cases for parse