Structured logging mod bosh and mod bosh socket #2823

aleklisi · 2020-08-18T13:14:18Z

This PR adds structered logging to mod_bosh and mod_bosh_socket.
It is created no to be merged to #2816 but not to mess up work for other devs.

codecov · 2020-08-18T13:28:33Z

Codecov Report

Merging #2823 into structured_logging will increase coverage by 5.34%.
The diff coverage is 50.94%.

@@                  Coverage Diff                   @@
##           structured_logging    #2823      +/-   ##
======================================================
+ Coverage               73.34%   78.69%   +5.34%     
======================================================
  Files                     373      373              
  Lines                   30929    30954      +25     
======================================================
+ Hits                    22686    24358    +1672     
+ Misses                   8243     6596    -1647

Impacted Files	Coverage Δ
src/mod_bosh_socket.erl	`79.68% <37.83%> (-2.08%)`	⬇️
src/mod_bosh.erl	`93.87% <81.25%> (+1.41%)`	⬆️
...system_metrics/service_mongoose_system_metrics.erl	`71.92% <0.00%> (-7.02%)`	⬇️
src/mam/mod_mam_rdbms_prefs.erl	`90.99% <0.00%> (-3.61%)`	⬇️
src/mam/mod_mam_utils.erl	`85.43% <0.00%> (-1.48%)`	⬇️
src/mod_muc_room.erl	`77.64% <0.00%> (+0.05%)`	⬆️
src/mod_roster.erl	`80.09% <0.00%> (+0.23%)`	⬆️
src/ejabberd_c2s.erl	`88.84% <0.00%> (+0.29%)`	⬆️
src/mod_vcard.erl	`76.44% <0.00%> (+0.41%)`	⬆️
... and 101 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 984b97c...e387b59. Read the comment docs.

leszke · 2020-08-18T13:42:55Z

src/mod_bosh.erl

-                       [Reason]),
+            ?LOG_ERROR(#{
+                issue => bosh_stop,
+                issue=>undefined_condition,


This will override the previous value :(

arcusfelis · 2020-08-18T13:57:55Z

src/mod_bosh.erl

@@ -174,7 +174,7 @@ init(Req, _Opts) ->
 info(accept_options, Req, State) ->
    Origin = cowboy_req:header(<<"origin">>, Req),
    Headers = ac_all(Origin),
-    ?DEBUG("OPTIONS response: ~p~n", [Headers]),
+    ?LOG_DEBUG(#{options_response => Headers}),


OK, what field is required.

?LOG_DEBUG(#{what => bosh_accept_options, text => <<"Handle OPTIONS request in Bosh">>, headers => Headers})

I will fix it in all other log maps too.

arcusfelis · 2020-08-18T13:59:10Z

src/mod_bosh.erl

@@ -161,7 +161,7 @@ node_cleanup(Acc, Node) ->
 -type option() :: {atom(), any()}.
 -spec init(req(), _Opts :: [option()]) -> {cowboy_loop, req(), rstate()}.
 init(Req, _Opts) ->
-    ?DEBUG("issue=bosh_init", []),
+    ?LOG_DEBUG(#{issue => bosh_init}),


I think we should log req field in this module where is possible. So we can format it later in logs.

arcusfelis · 2020-08-18T14:01:47Z

src/mod_bosh.erl

    %% Remember req_sid, so it can be used to print a debug message in bosh_reply
    forward_body(Req1, BodyElem, S#rstate{req_sid = Sid});
 info({bosh_reply, El}, Req, S) ->
    BEl = exml:to_binary(El),
-    ?DEBUG("issue=bosh_send sid=~ts req_sid=~ts reply_body=~p",
-           [exml_query:attr(El, <<"sid">>, <<"missing">>), S#rstate.req_sid, BEl]),
+    ?LOG_DEBUG(#{


?LOG_DEBUG(#{what => bosh_send, sid => exml_query:attr(El, <<"sid">>, <<"missing">>), req_sid => S#rstate.req_sid, reply_body => BEl}),

arcusfelis · 2020-08-18T14:51:55Z

src/mod_bosh_socket.erl

    {reply, ok, accumulate, State}.

 normal(Event, _From, State) ->
-    ?DEBUG("Unhandled sync event in 'normal' state: ~w~n", [Event]),
+    ?LOG_DEBUG(#{what => bosh_socket_unhandled_sync_event, state => normal,


state_name instead of state.
And indention for record should be different (second line should start below what).

arcusfelis · 2020-08-18T14:52:49Z

src/mod_bosh_socket.erl

@@ -341,7 +348,8 @@ handle_sync_event(get_cached_responses, _From, StateName,
                  #state{sent = CachedResponses} = S) ->
    {reply, CachedResponses, StateName, S};
 handle_sync_event(Event, _From, StateName, State) ->
-    ?DEBUG("Unhandled sync all state event: ~w~n", [Event]),
+    ?LOG_DEBUG(#{what => bosh_socket_unhandled_sync_all_state, state => State,


LOG_DEBUG(#{what => bosh_socket_unhandled_event,

arcusfelis · 2020-08-18T14:53:19Z

src/mod_bosh_socket.erl

@@ -373,11 +381,12 @@ handle_info(close, _SName, #state{pending = []} = State) ->
 handle_info(close, _SName, State) ->
    {next_state, closing, State};
 handle_info(inactivity_timeout, _SName, State) ->
-    ?INFO_MSG("terminating due to client inactivity~n", []),
+    ?LOG_INFO(#{what => bosh_socket_terminating, reason => "client inactivity"}),


text => <<"Terminating due to client inactivity">>

arcusfelis · 2020-08-18T14:54:08Z

src/mod_bosh_socket.erl

    {stop, {shutdown, inactivity_timeout}, State};
 handle_info({wait_timeout, {Rid, Pid}}, SName,
            #state{handlers = Handlers} = S) ->
-    ?INFO_MSG("'wait' limit reached for ~p~n", [Pid]),
+    ?LOG_INFO(#{what => bosh_socket_wait, reason => "process reached limit",


what => bosh_socket_wait_timeout. bosh_pid and rid fields.

arcusfelis · 2020-08-18T14:56:15Z

src/mod_bosh_socket.erl

@@ -389,15 +398,16 @@ handle_info({wait_timeout, {Rid, Pid}}, SName,
            {next_state, SName, NS}
    end;
 handle_info(Info, SName, State) ->
-    ?DEBUG("Unhandled info in '~s' state: ~w~n", [SName, Info]),
+    ?LOG_DEBUG(#{what => bosh_socket_unhandled_info, s_name => SName,
+        state => Info}),


msg => Info.
And we usually name that case as what => unexpected_message

arcusfelis · 2020-08-18T14:56:53Z

src/mod_bosh_socket.erl

    {next_state, SName, State}.

 terminate(_Reason, StateName, #state{sid = Sid, handlers = Handlers} = S) ->
    [Pid ! {close, Sid} || {_, _, Pid} <- lists:sort(Handlers)],
    mod_bosh_backend:delete_session(Sid),
    catch ejabberd_c2s:stop(S#state.c2s_pid),
-    ?DEBUG("Closing session ~p in '~s' state. Handlers: ~p Pending: ~p~n",
-           [Sid, StateName, Handlers, S#state.pending]).
+    ?LOG_DEBUG(#{what => bosh_socket_closing_session, session_id => Sid,


sid field name for consistency. And state_name

arcusfelis · 2020-08-18T14:57:56Z

src/mod_bosh_socket.erl

-            ?INFO_MSG("request ~p repeated but no response found in cache ~p~n",
-                      [Rid, Sent]),
+            ?LOG_INFO(#{what => bosh_socket_request_repeated, rid => Rid,
+                issue => "request repeated but no response found in cache",


text => <<"Bosh request repeated but no response found in cache">>

arcusfelis · 2020-08-18T14:59:30Z

src/mod_bosh_socket.erl

@@ -847,7 +857,8 @@ get_client_acks(streamstart, Element, Default) ->
        <<"1">> ->
            true;
        _ ->
-            ?INFO_MSG("ignoring invalid client ack on stream start~n", []),
+            ?LOG_INFO(#{what => bosh_socket_ignore_ack,
+                details => "ignoring invalid client ack on stream start"}),


text field instead of details. Text should be a binary.

arcusfelis · 2020-08-18T14:59:46Z

src/mod_bosh_socket.erl

+            ?LOG_DEBUG(#{
+                what => bosh_socket_cannot_send_stream_end,
+                issue => "can't send stream end",
+                reason => "pending stanzas"}),


include stanzas

arcusfelis · 2020-08-18T18:04:28Z

merged

aleklisi added 2 commits August 18, 2020 14:39

Use structured logging in mod_bosh

bf135ce

Use structered logging in mod_bosh_socket

c6c0281

aleklisi requested a review from arcusfelis August 18, 2020 13:14

Remove unsued function

654a229

Restore maybe_diff function

7a8d99e

aleklisi mentioned this pull request Aug 18, 2020

Structured logging #2816

Merged

17 tasks

leszke reviewed Aug 18, 2020

View reviewed changes

Fix repeated key issue

df31273

arcusfelis reviewed Aug 18, 2020

View reviewed changes

Apply code review found issues

e387b59

arcusfelis reviewed Aug 18, 2020

View reviewed changes

arcusfelis requested changes Aug 18, 2020

View reviewed changes

arcusfelis closed this Aug 18, 2020

NelsonVides deleted the structured_logging_mod_bosh_and_mod_bosh_socket branch August 18, 2020 18:04

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Structured logging mod bosh and mod bosh socket #2823

Structured logging mod bosh and mod bosh socket #2823

aleklisi commented Aug 18, 2020 •

edited

codecov bot commented Aug 18, 2020 •

edited

leszke Aug 18, 2020

aleklisi Aug 18, 2020

arcusfelis Aug 18, 2020

aleklisi Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis Aug 18, 2020

arcusfelis commented Aug 18, 2020

Structured logging mod bosh and mod bosh socket #2823

Structured logging mod bosh and mod bosh socket #2823

Conversation

aleklisi commented Aug 18, 2020 • edited

codecov bot commented Aug 18, 2020 • edited

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arcusfelis commented Aug 18, 2020

aleklisi commented Aug 18, 2020 •

edited

codecov bot commented Aug 18, 2020 •

edited