Merge pull request #1906 from esl/logging-docs

Add some logging docs

doc/developers-guide/logging.md

@@ -0,0 +1,112 @@
+# Logging
+
+To use logger in your module, include
+
+```erlang
+-include("mongoose_logger.hrl").
+```
+
+or
+
+```erlang
+-include("mongoose.hrl").
+```
+
+# Logging macros
+
+There are several macroses:
+
+```erlang
+DEBUG("event=debug_event info=~1000p", [Arg]),
+INFO_MSG("event=info_event info=~1000p", [Arg]),
+ERROR_MSG("event=error_event reason=~1000p", [Arg]),
+WARNING_MSG("event=warning_event reason=~1000p", [Arg]),
+```
+
+Use them to log on corresponding log level.
+
+Don't use `ERROR_MSG` for cases that are not errors.
+
+# Logging levels
+
+A system operator can choose log level by setting loglevel in `ejabberd.cfg`.
+
+- level 5 - debug
+- level 4 - info
+- level 3 - warning
+- level 2 - error
+- level 1 - critical
+- level 0 - none
+
+While there is a macro to log on level 1, we rarely use it.
+
+If an user sets log level 5, than he would see all messages in logs.
+
+Levels 3 or 2 are usually used for production systems.
+
+
+# Logging format
+
+We use modified [logfmt](https://brandur.org/logfmt) format.
+
+This format is [Splunk](https://www.splunk.com/en_us/solutions/solution-areas/log-management.html)
+and [ELK](https://www.elastic.co/elk-stack) friendly.
+
+`event=something_interesting` field is required.
+
+`reason=~1000p` field is commonly used.
+
+```erlang
+    ?ERROR_MSG("event=check_password_failed "
+               "reason=~p user=~ts", [Error, LUser]),
+
+    try ...
+    catch
+        Class:Reason ->
+            Stacktrace = erlang:get_stacktrace(),
+            ?ERROR_MSG("event=check_password_failed "
+                       "reason=~p:~p user=~ts stacktrace=~1000p",
+                       [Class, Reason, LUser, Stacktrace]),
+            erlang:raise(Class, Reason, Stacktrace)
+    end
+```
+
+`user=~ts` is often used too.
+
+
+A common way to name an error event is `event=function_name_failed`.
+For example, `event=remove_user_failed`. Use the advice critically, it would
+not work well for any function. Counter example:
+
+```erlang
+handle_info(Info, State) ->
+    ?ERROR_MSG("issue=unexpected_info_received info=~1000p", [Info]),
+    {noreply, State}.
+```
+
+Log messages should not contain new lines.
+
+We usually use `~1000p` to log long datastructures.
+
+Use whitespace as a field separator:
+
+```erlang
+%% Use
+?ERROR_MSG("event=check_password_failed reason=~p", [Reason])
+
+%% Don't use
+?ERROR_MSG("event=check_password_failed, reason=~p", [Reason])
+```
+
+# Filtering logs by module
+
+Setting loglevel to `debug` leads to a flood of messages in logs.
+To set different loglevel for just one module, call:
+
+```erlang
+ejabberd_loglevel:set(3).
+ejabberd_loglevel:set_custom(mod_mam, 5).
+```
+
+This code sets loglevel error for all messages, except generated by `mod_mam`.
+All messages from `mod_mam` would be logged.

mkdocs.yml

@@ -56,6 +56,7 @@ pages:
       - 'Distribution over TLS': 'operation-and-maintenance/tls-distribution.md'
   - "Developer's guide":
       - 'Testing MongooseIM': 'developers-guide/Testing-MongooseIM.md'
+      - 'Logging': 'developers-guide/logging.md'
       - 'Hooks and Handlers': 'developers-guide/Hooks-and-handlers.md'
       - 'Hooks description': 'developers-guide/hooks_description.md'
       - 'Stanza routing': 'developers-guide/message_routing.md'