ft: add warning log message if there is no readiness message sent

This is one of the most common issues that people encounter from my
experience when they are using this library together with `Type=notify`
systemd units. This adds message to warn user that they may have forgot
about sending that message. This should help with debugging reason for
seemingly unreasonable application restarts.

src/systemd.app.src

@@ -16,6 +16,7 @@
         {unset_env, true},
         {auto_formatter, true},
         {watchdog_scale, 2},
+        {warn_about_readiness_message, 10000},
         {logger, [
             {handler, systemd_journal, systemd_journal_h, #{
                 formatter => {logger_formatter, #{template => [msg]}}

src/systemd.erl

@@ -1,4 +1,4 @@
-
+%% Licensed to the Apache Software Foundation (ASF) under one
 %% or more contributor license agreements.  See the NOTICE file
 %% distributed with this work for additional information
 %% regarding copyright ownership.  The ASF licenses this file
@@ -183,6 +183,14 @@ normalize_state({_, _} = Msg) ->
 %% contains temporary job that will notify systemd about application readiness.
 %% This is meant to be inserted into your supervison tree when application is
 %% ready (usually at the end).
+%%
+%% == Details ==
+%%
+%% There will be warning in the log if there is no readiness message sent within
+%% 10 seconds of the `systemd' application start. That message timeout can be
+%% configured `systemd.warn_about_readiness_message' configuration option, it
+%% can be set either to positive integer which denotes amount of milliseconds
+%% until message, or it can be set to `false' to disable message completely.
 %% @end
 -spec ready() -> supervisor:child_spec().
 ready() ->

src/systemd_socket.erl

@@ -23,14 +23,16 @@
 
 -define(NAME, ?MODULE).
 
+-include_lib("kernel/include/logger.hrl").
+
 -export([send/3]).
 
 -export([
     start_link/1,
     init/1,
     handle_call/3,
     handle_cast/2,
-    terminate/2
+    handle_info/2
 ]).
 
 % # Internal interface
@@ -41,30 +43,36 @@ send(Data, Pid, Fds) when is_integer(Pid), is_list(Fds) ->
 
 % # Behaviour implementation
 
+-record(state, {socket, address, timer_ref}).
+
 start_link(Address) ->
     gen_server:start_link({local, ?NAME}, ?MODULE, Address, []).
 
 init([]) ->
     {ok, []};
 init(Address) ->
     {ok, Socket} = socket:open(local, dgram),
-    State = {Socket, Address},
+    TimerRef = set_timer(),
+    State = #state{socket = Socket, address = Address, timer_ref = TimerRef},
     _ = send_msg(State, systemd_protocol:encode([{"MAINPID", os:getpid()}]), 0, []),
-    {ok, {Socket, Address}}.
+    {ok, State}.
 
-handle_call({send, Message, Pid, Fds}, _Ref, State) ->
+handle_call({send, Message, Pid, Fds}, _Ref, State0) ->
+    State = clean_timer(Message, State0),
     {reply, send_msg(State, iolist_to_binary(Message), Pid, Fds), State}.
 
 handle_cast(_Msg, State) ->
     {noreply, State}.
 
-terminate(_Reason, {Socket, _Address}) ->
-    ok = socket:close(Socket),
-    ok.
+handle_info({ready_info, _Time}, State) ->
+    ?LOG_WARNING("systemd haven't received READY=1 message. "
+                 "You may forget to add systemd:ready() to your "
+                 "supervisor children list."),
+    {noreply, State#state{timer_ref = undefined}}.
 
 send_msg([], _Message, _Pid, _Fds) ->
     ok;
-send_msg({Socket, Address}, Message, Pid, Fds) ->
+send_msg(#state{socket = Socket, address = Address}, Message, Pid, Fds) ->
     Addr = #{family => local, path => Address},
     MsgHdr = #{
         addr => Addr,
@@ -77,6 +85,25 @@ send_msg({Socket, Address}, Message, Pid, Fds) ->
         {error, _} = Error -> Error
     end.
 
+set_timer() ->
+    case application:get_env(systemd, warn_about_readiness_message) of
+        {ok, Time} when is_integer(Time), Time > 0 ->
+            erlang:send_after(Time, self(), {ready_info, Time});
+        {ok, false} ->
+            undefined
+    end.
+
+clean_timer(Message, #state{timer_ref = Ref} = State) when is_reference(Ref) ->
+    case string:find(Message, "READY=1\n") of
+        nomatch ->
+            State;
+
+        _ ->
+            _ = erlang:cancel_timer(Ref),
+            State#state{timer_ref = undefined}
+    end;
+clean_timer(_, State) -> State.
+
 %% @TODO Implement this when there will be a reliable way to encode
 %% `cmsg_send()' with `credentials' type and there will be a way to get other
 %% process information from the OS (`GID', `EGID', `UID', and `EUID').
@@ -88,9 +115,9 @@ encode_fds([]) ->
 encode_fds(Fds) when is_list(Fds) ->
     Binary = <<<<Fd:32/native-integer>> || Fd <- Fds>>,
     [
-        #{
-            level => socket,
-            type => rights,
-            data => Binary
-        }
+     #{
+       level => socket,
+       type => rights,
+       data => Binary
+      }
     ].

src/systemd_watchdog.erl

@@ -34,7 +34,7 @@
     report_cb/1
 ]).
 
--record(state, {timeout, enabled = true}).
+-record(state, {timeout, enabled}).
 
 start_link(Config) ->
     gen_server:start_link({local, ?WATCHDOG}, ?MODULE, Config, []).

test/logger_send_back_h.erl

@@ -0,0 +1,6 @@
+-module(logger_send_back_h).
+
+-export([log/2]).
+
+log(Event, #{config := #{pid := Pid}}) ->
+    Pid ! Event.

test/systemd_SUITE.erl

@@ -15,7 +15,7 @@
     recv/1
 ]).
 
-all() -> [notify, ready, listen_fds, socket, fds].
+all() -> [notify, ready, ready_warning, listen_fds, socket, fds].
 
 init_per_testcase(Name, Config0) ->
     PrivDir = ?config(priv_dir, Config0),
@@ -106,6 +106,45 @@ ready(Config) ->
 
     ok.
 
+ready_warning(init, Config) ->
+    ok = logger:add_handler(send_back,
+                            logger_send_back_h,
+                            #{
+                              config => #{
+                                          pid => self()
+                                         }
+                             }),
+    application:set_env(systemd, warn_about_readiness_message, 1000),
+    Config;
+ready_warning(_, Config) ->
+    _ = logger:remove_handler(send_back),
+    application:set_env(systemd, warn_about_readiness_message, 10000),
+    stop(Config),
+    Config.
+
+ready_warning(Config) ->
+    Socket = ?config(socket, Config),
+    ok = start_with_socket(Socket),
+    ct:sleep(2000),
+    receive
+        #{msg := {string, Msg}, level := warning} ->
+            ?assert(string:find(Msg, "systemd haven't received READY=1") =/= nomatch),
+            ok
+    after
+        0 -> ct:fail("Haven't received any warning message")
+    end,
+    stop(Config),
+
+    ok = start_with_socket(Socket),
+    systemd:notify(ready),
+    ct:sleep(2000),
+    receive
+        #{msg := {string, _Msg}, level := warning} ->
+            ct:fail("Received warning even after sending ready message")
+    after
+        0 -> ok
+    end.
+
 listen_fds(init, Config) ->
     Config;
 listen_fds(finish, Config) ->