Improve logging during replicat initialization

Starting a replica and its reader can temporarily in some cases and
environment (e.g. when restarting a node on K8S, when DNS is not sorted
out yet). The current logging messages can be misleading and verbose.

This commit tries to avoid crash reports when a replica reader cannot
connect to its replica. This is usually a transient issue and the whole
crash report does not help much and clutters the log file.

References #186

Author: acogoluegnes

src/osiris_replica.erl

@@ -281,8 +281,15 @@ handle_continue(#{name := Name0,
                                        transport = Transport},
                               log = Log,
                               parse_state = undefined}};
+                {error, {connection_refused = R, _}} ->
+                    %% we don't log details for connection_refused,
+                    %% they are already in the logs of the other node
+                    ?WARN_(Name, "failed to start replica reader on node '~w'. "
+                           "Reason ~0p.", [Node, R]),
+                    {stop, {shutdown, R}, undefined};
                 {error, Reason} ->
-                    ?WARN_(Name, "failed to start replica reader. Reason ~0p", [Reason]),
+                    ?WARN_(Name, "failed to start replica reader on node '~w'. "
+                           "Reason ~0p.", [Node, Reason]),
                     {stop, {shutdown, Reason}, undefined}
             end
     end.
@@ -332,25 +339,31 @@ accept(Name, tcp, LSock, Process) ->
     end;
 accept(Name, ssl, LSock, Process) ->
     ?DEBUG_(Name, "Starting socket acceptor for replication over TLS", []),
-    {ok, Sock0} = ssl:transport_accept(LSock),
-    SslOptions = application:get_env(osiris, replication_server_ssl_options, []),
-    case ssl:handshake(Sock0, SslOptions) of
-        {ok, Sock} ->
-            _ = ssl:close(LSock),
-            ok = ssl:controlling_process(Sock, Process),
-            Process ! {socket, Sock},
-            ok;
-        {error, {tls_alert, {handshake_failure, _}}} ->
-            ?DEBUG_(Name, "Handshake failure, restarting listener...",
-                    []),
-            _ = spawn_link(fun() -> accept(Name, ssl, LSock, Process) end),
+    case ssl:transport_accept(LSock) of
+        {ok, Sock0} ->
+            SslOpts = application:get_env(osiris, replication_server_ssl_options, []),
+            case ssl:handshake(Sock0, SslOpts) of
+                {ok, Sock} ->
+                    _ = ssl:close(LSock),
+                    ok = ssl:controlling_process(Sock, Process),
+                    Process ! {socket, Sock},
+                    ok;
+                {error, {tls_alert, {handshake_failure, _}}} ->
+                    ?DEBUG_(Name, "Handshake failure, restarting listener...",
+                            []),
+                    _ = spawn_link(fun() -> accept(Name, ssl, LSock, Process) end),
+                    ok;
+                {error, E} ->
+                    ?DEBUG_(Name, "Error during handshake ~w", [E]);
+                H ->
+                    ?DEBUG_(Name, "Unexpected result from TLS handshake ~w", [H])
+            end,
             ok;
-        {error, E} ->
-            ?DEBUG_(Name, "Error during handshake ~w", [E]);
-        H ->
-            ?DEBUG_(Name, "Unexpected result from TLS handshake ~w", [H])
-    end,
-    ok.
+        {error, Err} ->
+            ?DEBUG_(Name, "ssl:transport_accept/1 failed with ~0p", [Err]),
+            _ = ssl:close(LSock),
+            ok
+    end.
 
 %%--------------------------------------------------------------------
 %% @private

src/osiris_replica_reader.erl

@@ -117,11 +117,10 @@ init(#{hosts := Hosts,
 
     ?DEBUG("~ts: trying to connect to replica at ~0p", [Name, Hosts]),
 
-    case maybe_connect(Name, Transport, Hosts, Port, connect_options())
-    of
+    case maybe_connect(Name, Transport, Hosts, Port, connect_options()) of
         {ok, Sock, Host} ->
-            ?DEBUG_(Name, "successfully connected to host ~0p port ~b",
-                    [Host, Port]),
+            ?INFO_(Name, "replica reader successfully connected to host ~0p port ~b",
+                   [Host, Port]),
             CntId = {?MODULE, ExtRef, Host, Port},
             CntSpec = {CntId, ?COUNTER_FIELDS},
             Config = #{counter_spec => CntSpec, transport => Transport},
@@ -177,7 +176,7 @@ init(#{hosts := Hosts,
         {error, Reason} ->
             ?WARN_(Name, "could not connect replica reader to replica at ~0p port ~b, Reason: ~0p",
                    [Hosts, Port, Reason]),
-            {stop, Reason}
+            {error, Reason}
     end.
 
 %%--------------------------------------------------------------------
@@ -391,34 +390,40 @@ setopts(tcp, Sock, Opts) ->
 setopts(ssl, Sock, Opts) ->
     ok = ssl:setopts(Sock, Opts).
 
-maybe_connect(_Name, _, [], _Port, _Options) ->
+
+maybe_connect(Name, T, Hosts, Port, Options) ->
+    maybe_connect(Name, T, Hosts, Port, Options, []).
+
+maybe_connect(Name, _, [], Port, _Options, Acc) ->
+    ?INFO_(Name, "could not connect replica reader to replica on port ~b, "
+           "reason(s): ~0p", [Port, Acc]),
     {error, connection_refused};
-maybe_connect(Name, tcp, [H | T], Port, Options) ->
+maybe_connect(Name, tcp, [H | T], Port, Options, Acc) ->
     ?DEBUG_(Name, "trying to connect to ~0p on port ~b", [H, Port]),
     case gen_tcp:connect(H, Port, Options) of
         {ok, Sock} ->
             {ok, Sock, H};
         {error, Reason} ->
             ?DEBUG_(Name, "connection refused, reason: ~w host:~0p - port: ~0p",
                     [Reason, H, Port]),
-            maybe_connect(Name, tcp, T, Port, Options)
+            maybe_connect(Name, tcp, T, Port, Options, [{H, Reason} | Acc])
     end;
-maybe_connect(Name, ssl, [H | T], Port, Options) ->
+maybe_connect(Name, ssl, [H | T], Port, Options, Acc) ->
     ?DEBUG_(Name, "trying to establish TLS connection to ~0p using port ~b", [H, Port]),
     Opts = Options ++
         application:get_env(osiris, replication_client_ssl_options, []) ++
         maybe_add_sni_option(H),
     case ssl:connect(H, Port, Opts) of
         {ok, Sock} ->
             {ok, Sock, H};
-        {error, {tls_alert, {handshake_failure, _}}} ->
+        {error, {tls_alert, {handshake_failure = R, _}}} ->
             ?DEBUG_(Name, "TLS connection refused (handshake failure), host:~0p - port: ~0p",
                     [H, Port]),
-            maybe_connect(Name, ssl, T, Port, Options);
+            maybe_connect(Name, ssl, T, Port, Options, [{H, R} | Acc]);
         {error, E} ->
             ?DEBUG_(Name, "TLS connection refused, host:~0p - port: ~0p", [H, Port]),
             ?DEBUG_(Name, "error while trying to establish TLS connection ~0p", [E]),
-            maybe_connect(Name, ssl, T, Port, Options)
+            maybe_connect(Name, ssl, T, Port, Options, [{H, E} | Acc])
     end.
 
 maybe_add_sni_option(H) when is_binary(H) ->