Use structured logging (#29)

* Use structured logging * Update src/template_compiler_runtime_internal.erl * Normalize log statements with Zotonic log formats. * Readable Yecc errors. Co-authored-by: Marc Worrell <[email protected]> Co-authored-by: Viacheslav Katsuba <[email protected]>
zotonic · May 30, 2022 · a600e32 · a600e32
1 parent 2406174
commit a600e32
Show file tree

Hide file tree

Showing 4 changed files with 130 additions and 38 deletions.
diff --git a/src/template_compiler.erl b/src/template_compiler.erl
@@ -196,7 +196,12 @@ block_lookup({ok, TplFile}, BlockMap, ExtendsStack, DebugTrace, Options, Vars, R
             case lists:member(Module, ExtendsStack) of
                 true ->
                     FileTrace = [Module:filename() | [ M:filename() || M <- ExtendsStack ]],
-                    ?LOG_ERROR("[template_compiler] Template recursion: ~p", [FileTrace]),
+                    ?LOG_ERROR(#{
+                        text => <<"Template recursion">>,
+                        result => error,
+                        reason => recursion,
+                        trace => FileTrace
+                    }),
                     {error, {recursion, [Trace|DebugTrace]}};
                 false ->
                     % Check extended/overruled templates (build block map)
@@ -285,7 +290,11 @@ compile_binary(Tpl, Filename, Options, Context) when is_binary(Tpl) ->
                     {ok, Module};
                 false ->
                     Runtime:trace_compile(Module, Filename, Options, Context),
-                    case compile_tokens(template_compiler_parser:parse(Tokens2), cs(Module, Filename, Options, Context)) of
+                    case compile_tokens(
+                            template_compiler_parser:parse(Tokens2),
+                            cs(Module, Filename, Options, Context),
+                            Options)
+                    of
                         {ok, {Extends, BlockAsts, TemplateAst, IsAutoid}} ->
                             Forms = template_compiler_module:compile(
                                                 Module, Filename, Mtime, IsAutoid, Runtime,
@@ -354,17 +363,33 @@ compile_forms(Filename, Forms) ->
             case code:load_binary(Module, atom_to_list(Module) ++ ".erl", Bin) of
                 {module, _Module} ->
                     {ok, Module};
-                Error ->
-                    ?LOG_ERROR("Error loading compiling forms for ~p: ~p",
-                                [Filename, Error]),
+                {error, Reason} = Error ->
+                    ?LOG_ERROR(#{
+                        text => <<"Error loading compiling forms">>,
+                        module => Module,
+                        filename => Filename,
+                        result => error,
+                        reason => Reason
+                    }),
                     Error
             end;
         error ->
-            ?LOG_ERROR("Error compiling forms for ~p", [Filename]),
+            ?LOG_ERROR(#{
+                text => <<"Error compiling forms">>,
+                result => error,
+                reason => compile,
+                filename => Filename
+            }),
             {error, {compile, []}};
         {error, Es, Ws} ->
-            ?LOG_ERROR("Errors compiling ~p: ~p  (warnings ~p)",
-                        [Filename, Es, Ws]),
+            ?LOG_ERROR(#{
+                text => <<"Errors compiling">>,
+                filename => Filename,
+                result => error,
+                reason => compile,
+                errors => Es,
+                warnings => Ws
+            }),
             {error, {compile, Es, Ws}}
     end.
 
@@ -377,23 +402,62 @@ cs(Module, Filename, Options, Context) ->
         context=Context
     }.
 
-compile_tokens({ok, {extends, {string_literal, _, Extend}, Elements}}, CState) ->
+compile_tokens({ok, {extends, {string_literal, _, Extend}, Elements}}, CState, _Options) ->
     Blocks = find_blocks(Elements),
     {Ws, BlockAsts} = compile_blocks(Blocks, CState),
     {ok, {Extend, BlockAsts, undefined, Ws#ws.is_autoid_var}};
-compile_tokens({ok, {overrules, Elements}}, CState) ->
+compile_tokens({ok, {overrules, Elements}}, CState, _Options) ->
     Blocks = find_blocks(Elements),
     {Ws, BlockAsts} = compile_blocks(Blocks, CState),
     {ok, {overrules, BlockAsts, undefined, Ws#ws.is_autoid_var}};
-compile_tokens({ok, {base, Elements}}, CState) ->
+compile_tokens({ok, {base, Elements}}, CState, _Options) ->
     Blocks = find_blocks(Elements),
     {Ws, BlockAsts} = compile_blocks(Blocks, CState),
     CStateElts = CState#cs{blocks = BlockAsts},
     {Ws1, TemplateAsts} = template_compiler_element:compile(Elements, CStateElts, Ws),
     {ok, {undefined, BlockAsts, TemplateAsts, Ws1#ws.is_autoid_var}};
-compile_tokens({error, _} = Error, _CState) ->
+compile_tokens({error, {Loc, template_compiler_parser, Msg}}, #cs{ filename = Filename }, Options) ->
+    % Try format the Yecc error
+    Err = split_loc(Loc),
+    Stack = [
+        {filename:basename(Filename), render, 1, [
+            {file, maps:get(at, Err)},
+            {line, {maps:get(line, Err), maps:get(column, Err)}}
+        ]}
+        | case proplists:get_value(trace_position, Options) of
+            {SrcFile, SrcLine, _SrcCol} ->
+                [
+                    {filename:basename(SrcFile), render, 1, [
+                        {file, SrcFile},
+                        {line, SrcLine}
+                    ]}
+                ];
+            undefined ->
+                []
+        end
+    ],
+    Err1 = Err#{
+        result => error,
+        reason => syntax,
+        text => iolist_to_binary(Msg),
+        stack => Stack
+    },
+    {error, Err1};
+compile_tokens({error, _} = Error, _CState, _Options) ->
     Error.
 
+split_loc({Filename, Line, Col}) ->
+    #{
+        at => Filename,
+        line => Line,
+        column => Col
+    };
+split_loc({Filename, Line}) ->
+    #{
+        at => Filename,
+        line => Line
+    }.
+
 -spec compile_blocks([block_element()], #cs{}) -> {#ws{}, [{atom(), erl_syntax:syntaxTree()}]}.
 compile_blocks(Blocks, CState) ->
     Ws = #ws{},

diff --git a/src/template_compiler_admin.erl b/src/template_compiler_admin.erl
@@ -86,13 +86,13 @@ compile_file(Filename, TplKey, Options, Context) ->
                         What:Error:Stack ->
                             % io:format("Error compiling template ~p: ~p:~n~p at~n ~p~n",
                             %           [Filename, What, Error, Stack]),
-                            ?LOG_ERROR(
-                                "Error compiling template ~p: ~p: ~p",
-                                [Filename, What, Error],
-                                #{
-                                    template => Filename,
-                                    stack => Stack
-                                }),
+                            ?LOG_ERROR(#{
+                                text => <<"Error compiling template">>,
+                                template => Filename,
+                                result => What,
+                                reason => Error,
+                                stack => Stack
+                            }),
                             {error, Error}
                      end,
             ok = gen_server:call(?MODULE, {compile_done, Result, TplKey}, infinity),
@@ -220,8 +220,12 @@ handle_cast(Msg, State) ->
 handle_info({'DOWN', MRef, process, _Pid, Reason}, State) ->
     case lists:keytake(MRef, 1, State#state.compiling) of
         {value, {_MRef, TplKey, _From}, Compiling1} ->
-            ?LOG_ERROR("[template_compiler] Process compiling ~p down (reason ~p), restarting other waiter",
-                        [TplKey, Reason]),
+            ?LOG_ERROR(#{
+                text => <<"Compiler process down; restarting with other waiter">>,
+                tpl_key => TplKey,
+                result => error,
+                reason => Reason
+            }),
             {noreply, restart_compile(TplKey, State#state{compiling=Compiling1})};
         false ->
             {noreply, State}

diff --git a/src/template_compiler_runtime.erl b/src/template_compiler_runtime.erl
@@ -402,11 +402,17 @@ escape(Value, _Context) ->
 trace_compile(_Module, Filename, Options, _Context) ->
     case proplists:get_value(trace_position, Options) of
         {File, Line, _Col} ->
-            ?LOG_DEBUG("[template_compiler] Compiling \"~s\" (called from \"~s:~p\")",
-                        [Filename, File, Line]);
+            ?LOG_DEBUG(#{
+                text => <<"Compiling template">>,
+                filename => Filename,
+                at => File,
+                line => Line
+            });
         undefined ->
-            ?LOG_DEBUG("[template_compiler] Compiling \"~s\"",
-                        [Filename])
+            ?LOG_DEBUG(#{
+                text => <<"Compiling template">>,
+                filename => Filename
+            })
     end,
     ok.
 
@@ -416,11 +422,17 @@ trace_compile(_Module, Filename, Options, _Context) ->
 trace_render(Filename, Options, _Context) ->
     case proplists:get_value(trace_position, Options) of
         {File, Line, _Col} ->
-            ?LOG_DEBUG("[template_compiler] Include by \"~s:~p\" of \"~s\"",
-                        [File, Line, Filename]);
+            ?LOG_DEBUG(#{
+                text => <<"Template include">>,
+                filename => Filename,
+                at => File,
+                line => Line
+            });
         undefined ->
-            ?LOG_DEBUG("[template_compiler] Render \"~s\"",
-                        [Filename])
+            ?LOG_DEBUG(#{
+                text => <<"Template render">>,
+                filename => Filename
+            })
     end,
     ok.
 

diff --git a/src/template_compiler_runtime_internal.erl b/src/template_compiler_runtime_internal.erl
@@ -215,6 +215,7 @@ include_1(SrcPos, all, Template, Runtime, ContextVars, Vars1, Context) ->
             end,
             Templates);
 include_1(SrcPos, Method, Template, Runtime, ContextVars, Vars1, Context) ->
+    {SrcFile, SrcLine, _SrcCol} = SrcPos,
     Options = [
         {runtime, Runtime},
         {trace_position, SrcPos},
@@ -224,20 +225,31 @@ include_1(SrcPos, Method, Template, Runtime, ContextVars, Vars1, Context) ->
         {ok, Result} ->
             Result;
         {error, enoent} when Method =:= normal ->
-            ?LOG_ERROR("Missing included template ~p", [Template]),
+            ?LOG_ERROR(#{
+                text => <<"Included template not found">>,
+                template => Template,
+                srcpos => SrcPos,
+                result => error,
+                reason => enoent,
+                at => SrcFile,
+                line => SrcLine
+            }),
             <<>>;
         {error, enoent} ->
             <<>>;
-        {error, Reason} when is_list(Reason); is_binary(Reason) ->
-            R1 = try
-                iolist_to_binary(Reason)
-            catch _:_ ->
-                Reason
-            end,
-            ?LOG_ERROR("Template render error: '~s' for template ~p", [R1, Template]),
+        {error, Err} when is_map(Err) ->
+            ?LOG_ERROR(Err),
             <<>>;
         {error, Reason} ->
-            ?LOG_ERROR("Template render error: ~p for template ~p", [Reason, Template]),
+            ?LOG_ERROR(#{
+                text => <<"Template render error">>,
+                template => Template,
+                srcpos => SrcPos,
+                result => error,
+                reason => Reason,
+                at => SrcFile,
+                line => SrcLine
+            }),
             <<>>
     end.