Skip to content

Commit cb11325

Browse files
martosaurmartosaur
committed
Add log translation guide
1 parent 0e493bb commit cb11325

2 files changed

Lines changed: 386 additions & 1 deletion

File tree

‎guides/translation.md‎

Lines changed: 381 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,381 @@
1+
# Log Translation
2+
3+
Elixir and Erlang are different languages, but Elixir runs on the Erlang
4+
platform and it doesn't take much time until the platform starts to manifest
5+
itself. A lot of common errors originate in Erlang and if printed as-is, look
6+
foreign in the context of Elixir applications. To avoid this, Elixir performs
7+
something called log translation. This is one of the main functions of `Logger`
8+
applications Compare these two GenServer errors, with and without translation:
9+
10+
<!-- tabs-open -->
11+
12+
### With Translation
13+
14+
```text
15+
13:43:32.538 [error] GenServer #PID<0.198.0> terminating
16+
** (RuntimeError) oops
17+
(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: anonymous fn/0 in LoggerHandlerKit.Act.genserver_crash/1
18+
(stdlib 6.2.2) gen_server.erl:2381: :gen_server.try_handle_call/4
19+
(stdlib 6.2.2) gen_server.erl:2410: :gen_server.handle_msg/6
20+
(stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3
21+
Last message (from #PID<0.197.0>): {:run, #Function<16.413966/0 in LoggerHandlerKit.Act.genserver_crash/1>}
22+
State: nil
23+
Client #PID<0.197.0> is alive
24+
25+
(stdlib 6.2.2) gen.erl:260: :gen.do_call/4
26+
(elixir 1.19.0-dev) lib/gen_server.ex:1139: GenServer.call/3
27+
(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: LoggerHandlerKit.Act.genserver_crash/1
28+
(elixir 1.19.0-dev) src/elixir.erl:363: :elixir.eval_external_handler/3
29+
(stdlib 6.2.2) erl_eval.erl:919: :erl_eval.do_apply/7
30+
(elixir 1.19.0-dev) src/elixir.erl:341: :elixir.eval_forms/4
31+
(elixir 1.19.0-dev) lib/module/parallel_checker.ex:141: Module.ParallelChecker.verify/1
32+
(iex 1.19.0-dev) lib/iex/evaluator.ex:340: IEx.Evaluator.eval_and_inspect/3
33+
```
34+
35+
### Without Translation
36+
37+
```text
38+
13:44:53.011 [error] ** Generic server <0.199.0> terminating
39+
** Last message in was {run,#Fun<Elixir.LoggerHandlerKit.Act.16.413966>}
40+
** When Server state == nil
41+
** Reason for termination ==
42+
** {#{message => <<"oops">>,'__struct__' => 'Elixir.RuntimeError',
43+
'__exception__' => true},
44+
[{'Elixir.LoggerHandlerKit.Act','-genserver_crash/1-fun-0-',0,
45+
[{file,"lib/logger_handler_kit/act.ex"},
46+
{line,528},
47+
{error_info,#{module => 'Elixir.Exception'}}]},
48+
{gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,2381}]},
49+
{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,2410}]},
50+
{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,329}]}]}
51+
** Client <0.197.0> stacktrace
52+
** [{gen,do_call,4,[{file,"gen.erl"},{line,260}]},
53+
{'Elixir.GenServer',call,3,[{file,"lib/gen_server.ex"},{line,1139}]},
54+
{'Elixir.LoggerHandlerKit.Act',genserver_crash,1,
55+
[{file,"lib/logger_handler_kit/act.ex"},
56+
{line,528}]},
57+
{elixir,eval_external_handler,3,[{file,"src/elixir.erl"},{line,363}]},
58+
{erl_eval,do_apply,7,[{file,"erl_eval.erl"},{line,919}]},
59+
{elixir,eval_forms,4,[{file,"src/elixir.erl"},{line,341}]},
60+
{'Elixir.Module.ParallelChecker',verify,1,
61+
[{file,"lib/module/parallel_checker.ex"},
62+
{line,141}]},
63+
{'Elixir.IEx.Evaluator',eval_and_inspect,3,
64+
[{file,"lib/iex/evaluator.ex"},{line,340}]}]
65+
66+
67+
13:44:53.016 [error] crasher:
68+
initial call: 'Elixir.LoggerHandlerKit.GenServer':init/1
69+
pid: <0.199.0>
70+
registered_name: []
71+
exception error: #Elixir.RuntimeError
72+
in function 'Elixir.LoggerHandlerKit.Act':'-genserver_crash/1-fun-0-'/0 (lib/logger_handler_kit/act.ex, line 528)
73+
*** oops
74+
in call from gen_server:try_handle_call/4 (gen_server.erl, line 2381)
75+
in call from gen_server:handle_msg/6 (gen_server.erl, line 2410)
76+
ancestors: [<0.197.0>,<0.98.0>]
77+
message_queue_len: 0
78+
messages: []
79+
links: []
80+
dictionary: [{'$callers',[<0.197.0>]}]
81+
trap_exit: false
82+
status: running
83+
heap_size: 6772
84+
stack_size: 29
85+
reductions: 19158
86+
neighbours: []
87+
```
88+
89+
<!-- tabs-close -->
90+
91+
It's very clear how important translation is for people who are fluent primarily
92+
in Elixir.
93+
94+
## Translation is a Filter
95+
96+
Log translation is implemented as a primary filter, which means it will be
97+
called before handlers and any handler-specific filters. Remember that filters
98+
and logger configuration in general can be altered by users, although it's
99+
somewhat uncommon to remove or modify the `logger_translator` specifically.
100+
101+
To better visualize this, here is where the translation happens:
102+
103+
```elixir
104+
iex(1)> :logger.get_primary_config()
105+
%{
106+
level: :debug,
107+
filter_default: :log,
108+
filters: [
109+
# Here it is! Translation filter
110+
logger_translator: {&Logger.Utils.translator/2,
111+
%{otp: true, sasl: false, translators: [{Logger.Translator, :translate}]}},
112+
logger_process_level: {&Logger.Utils.process_level/2, []}
113+
],
114+
metadata: %{}
115+
}
116+
```
117+
118+
## 1.18 vs 1.19+
119+
120+
Before Elixir 1.19, log translation used to _replace_ the original Erlang
121+
structured report with an unstructured log message. If a handler wanted to access
122+
some of the data in the original report, it had to parse the log message.
123+
Starting from Elixir 1.19, translation is _inserted into_ the report, thus
124+
making the original report accessible to the handlers. Here is an example:
125+
126+
<!-- tabs-open -->
127+
128+
### Before Translation
129+
130+
```elixir
131+
%{
132+
meta: %{
133+
error_logger: %{tag: :error_report, type: :crash_report},
134+
line: 950,
135+
pid: #PID<0.203.0>,
136+
time: 1746910751187661,
137+
file: ~c"proc_lib.erl",
138+
gl: #PID<0.70.0>,
139+
domain: [:otp, :sasl],
140+
logger_formatter: %{title: ~c"CRASH REPORT"},
141+
mfa: {:proc_lib, :crash_report, 4},
142+
report_cb: &:proc_lib.report_cb/2
143+
},
144+
msg: {:report,
145+
%{
146+
label: {:proc_lib, :crash},
147+
report: [
148+
[
149+
initial_call: {LoggerHandlerKit.GenServer, :init, [:Argument__1]},
150+
pid: #PID<0.203.0>,
151+
registered_name: [],
152+
process_label: :undefined,
153+
error_info: {:error, %RuntimeError{message: "oops"},
154+
[
155+
{LoggerHandlerKit.Act, :"-genserver_crash/1-fun-0-", 0,
156+
[
157+
file: ~c"lib/logger_handler_kit/act.ex",
158+
line: 528,
159+
error_info: %{module: Exception}
160+
]},
161+
{:gen_server, :try_handle_call, 4,
162+
[file: ~c"gen_server.erl", line: 2381]},
163+
{:gen_server, :handle_msg, 6,
164+
[file: ~c"gen_server.erl", line: 2410]},
165+
{:proc_lib, :init_p_do_apply, 3,
166+
[file: ~c"proc_lib.erl", line: 329]}
167+
]},
168+
ancestors: [#PID<0.197.0>, #PID<0.98.0>],
169+
message_queue_len: 0,
170+
messages: [],
171+
links: [],
172+
dictionary: ["$callers": [#PID<0.197.0>]],
173+
trap_exit: false,
174+
status: :running,
175+
heap_size: 1598,
176+
stack_size: 29,
177+
reductions: 28455
178+
],
179+
[]
180+
]
181+
}},
182+
level: :error
183+
}
184+
```
185+
186+
### 1.18 Translation
187+
188+
```elixir
189+
%{
190+
meta: %{
191+
error_logger: %{tag: :error, report_cb: &:gen_server.format_log/1},
192+
line: 2646,
193+
pid: #PID<0.1105.0>,
194+
time: 1746911049539570,
195+
file: ~c"gen_server.erl",
196+
gl: #PID<0.70.0>,
197+
domain: [:otp],
198+
report_cb: &:gen_server.format_log/2,
199+
mfa: {:gen_server, :error_info, 8},
200+
crash_reason: {%RuntimeError{message: "oops"},
201+
[
202+
{LoggerHandlerKit.Act, :"-genserver_crash/1-fun-0-", 0,
203+
[
204+
file: ~c"lib/logger_handler_kit/act.ex",
205+
line: 528,
206+
error_info: %{module: Exception}
207+
]},
208+
{:gen_server, :try_handle_call, 4,
209+
[file: ~c"gen_server.erl", line: 2381]},
210+
{:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl", line: 2410]},
211+
{:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
212+
]}
213+
},
214+
msg: {:string,
215+
[
216+
[
217+
"GenServer ",
218+
"#PID<0.1105.0>",
219+
" terminating",
220+
[
221+
[10 | "** (RuntimeError) oops"],
222+
["\n " |
223+
"(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: anonymous fn/0 in LoggerHandlerKit.Act.genserver_crash/1"],
224+
["\n " |
225+
"(stdlib 6.2.2) gen_server.erl:2381: :gen_server.try_handle_call/4"],
226+
["\n " |
227+
"(stdlib 6.2.2) gen_server.erl:2410: :gen_server.handle_msg/6"],
228+
["\n " |
229+
"(stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3"]
230+
],
231+
[],
232+
"\nLast message",
233+
[" (from ", "#PID<0.1099.0>", ")"],
234+
": ",
235+
"{:run, #Function<16.413966/0 in LoggerHandlerKit.Act.genserver_crash/1>}"
236+
],
237+
"\nState: ",
238+
"nil",
239+
"\nClient ",
240+
"#PID<0.1099.0>",
241+
" is alive\n",
242+
["\n " | "(stdlib 6.2.2) gen.erl:260: :gen.do_call/4"],
243+
["\n " | "(elixir 1.18.3) lib/gen_server.ex:1125: GenServer.call/3"],
244+
["\n " |
245+
"(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: LoggerHandlerKit.Act.genserver_crash/1"],
246+
["\n " |
247+
"(elixir 1.18.3) src/elixir.erl:386: :elixir.eval_external_handler/3"],
248+
["\n " | "(stdlib 6.2.2) erl_eval.erl:919: :erl_eval.do_apply/7"],
249+
["\n " | "(elixir 1.18.3) src/elixir.erl:364: :elixir.eval_forms/4"],
250+
["\n " |
251+
"(elixir 1.18.3) lib/module/parallel_checker.ex:120: Module.ParallelChecker.verify/1"],
252+
["\n " |
253+
"(iex 1.18.3) lib/iex/evaluator.ex:336: IEx.Evaluator.eval_and_inspect/3"]
254+
]},
255+
level: :error
256+
}
257+
```
258+
259+
### 1.19 Translation
260+
261+
```elixir
262+
%{
263+
meta: %{
264+
error_logger: %{tag: :error, report_cb: &:gen_server.format_log/1},
265+
line: 2646,
266+
pid: #PID<0.205.0>,
267+
time: 1746910905177484,
268+
file: ~c"gen_server.erl",
269+
gl: #PID<0.70.0>,
270+
domain: [:otp],
271+
mfa: {:gen_server, :error_info, 8},
272+
report_cb: &Logger.Utils.translated_cb/1,
273+
crash_reason: {%RuntimeError{message: "oops"},
274+
[
275+
{LoggerHandlerKit.Act, :"-genserver_crash/1-fun-0-", 0,
276+
[
277+
file: ~c"lib/logger_handler_kit/act.ex",
278+
line: 528,
279+
error_info: %{module: Exception}
280+
]},
281+
{:gen_server, :try_handle_call, 4,
282+
[file: ~c"gen_server.erl", line: 2381]},
283+
{:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl", line: 2410]},
284+
{:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
285+
]}
286+
},
287+
msg: {:report,
288+
%{
289+
label: {:gen_server, :terminate},
290+
name: #PID<0.205.0>,
291+
reason: {%RuntimeError{message: "oops"},
292+
[
293+
{LoggerHandlerKit.Act, :"-genserver_crash/1-fun-0-", 0,
294+
[
295+
file: ~c"lib/logger_handler_kit/act.ex",
296+
line: 528,
297+
error_info: %{module: Exception}
298+
]},
299+
{:gen_server, :try_handle_call, 4,
300+
[file: ~c"gen_server.erl", line: 2381]},
301+
{:gen_server, :handle_msg, 6, [file: ~c"gen_server.erl", line: 2410]},
302+
{:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 329]}
303+
]},
304+
log: [],
305+
state: nil,
306+
process_label: :undefined,
307+
last_message: {:run,
308+
#Function<16.413966/0 in LoggerHandlerKit.Act.genserver_crash/1>},
309+
client_info: {#PID<0.197.0>,
310+
{#PID<0.197.0>,
311+
[
312+
{:gen, :do_call, 4, [file: ~c"gen.erl", line: 260]},
313+
{GenServer, :call, 3, [file: ~c"lib/gen_server.ex", line: 1139]},
314+
{LoggerHandlerKit.Act, :genserver_crash, 1,
315+
[file: ~c"lib/logger_handler_kit/act.ex", line: 528]},
316+
{:elixir, :eval_external_handler, 3,
317+
[file: ~c"src/elixir.erl", line: 363]},
318+
{:erl_eval, :do_apply, 7, [file: ~c"erl_eval.erl", line: 919]},
319+
{:elixir, :eval_forms, 4, [file: ~c"src/elixir.erl", line: 341]},
320+
{Module.ParallelChecker, :verify, 1,
321+
[file: ~c"lib/module/parallel_checker.ex", line: 141]},
322+
{IEx.Evaluator, :eval_and_inspect, 3,
323+
[file: ~c"lib/iex/evaluator.ex", line: 340]}
324+
]}},
325+
elixir_translation: [
326+
[
327+
"GenServer ",
328+
"#PID<0.205.0>",
329+
" terminating",
330+
[
331+
[10 | "** (RuntimeError) oops"],
332+
["\n " |
333+
"(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: anonymous fn/0 in LoggerHandlerKit.Act.genserver_crash/1"],
334+
["\n " |
335+
"(stdlib 6.2.2) gen_server.erl:2381: :gen_server.try_handle_call/4"],
336+
["\n " |
337+
"(stdlib 6.2.2) gen_server.erl:2410: :gen_server.handle_msg/6"],
338+
["\n " |
339+
"(stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3"]
340+
],
341+
[],
342+
"\nLast message",
343+
[" (from ", "#PID<0.197.0>", ")"],
344+
": ",
345+
"{:run, #Function<16.413966/0 in LoggerHandlerKit.Act.genserver_crash/1>}"
346+
],
347+
"\nState: ",
348+
"nil",
349+
"\nClient ",
350+
"#PID<0.197.0>",
351+
" is alive\n",
352+
["\n " | "(stdlib 6.2.2) gen.erl:260: :gen.do_call/4"],
353+
["\n " |
354+
"(elixir 1.19.0-dev) lib/gen_server.ex:1139: GenServer.call/3"],
355+
["\n " |
356+
"(logger_handler_kit 0.1.0) lib/logger_handler_kit/act.ex:528: LoggerHandlerKit.Act.genserver_crash/1"],
357+
["\n " |
358+
"(elixir 1.19.0-dev) src/elixir.erl:363: :elixir.eval_external_handler/3"],
359+
["\n " | "(stdlib 6.2.2) erl_eval.erl:919: :erl_eval.do_apply/7"],
360+
["\n " |
361+
"(elixir 1.19.0-dev) src/elixir.erl:341: :elixir.eval_forms/4"],
362+
["\n " |
363+
"(elixir 1.19.0-dev) lib/module/parallel_checker.ex:141: Module.ParallelChecker.verify/1"],
364+
["\n " |
365+
"(iex 1.19.0-dev) lib/iex/evaluator.ex:340: IEx.Evaluator.eval_and_inspect/3"]
366+
]
367+
}},
368+
level: :error
369+
}
370+
```
371+
372+
<!-- tabs-close -->
373+
374+
## More Than Translation
375+
376+
In addition to translating logs, the `logger_translator` filter is also responsible
377+
for enforcing the `handle_otp_reports` and `handle_sasl_reports` [configuration
378+
options](https://hexdocs.pm/logger/Logger.html#module-boot-configuration). This
379+
is worth keeping in mind and may come up during debugging. Trying to understand
380+
which part of the system dropped an OTP log event may lead to the surprising
381+
discovery that the logger translator did it.

0 commit comments

Comments
 (0)