From a600e32409b53da60f9ae64a9a2bd9881cd67b1e Mon Sep 17 00:00:00 2001 From: MM Zeeman Date: Mon, 30 May 2022 17:52:06 +0200 Subject: [PATCH] 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 Co-authored-by: Viacheslav Katsuba --- src/template_compiler.erl | 88 +++++++++++++++++++--- src/template_compiler_admin.erl | 22 +++--- src/template_compiler_runtime.erl | 28 +++++-- src/template_compiler_runtime_internal.erl | 30 +++++--- 4 files changed, 130 insertions(+), 38 deletions(-) diff --git a/src/template_compiler.erl b/src/template_compiler.erl index dc3d1cd..28079f5 100644 --- 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 index a97f6fd..0abd7be 100644 --- 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 index 4e07c38..2fdb0e9 100644 --- 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 index 3f97b05..1dbc9ac 100644 --- 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.