Skip to content

Commit 884de18

Browse files
martosaurmartosaur
authored
Preserve logger reports through translation by encapculating translated output in report_cb (#14380)
1 parent 2a2765c commit 884de18

File tree

2 files changed

+83
-54
lines changed

2 files changed

+83
-54
lines changed

‎lib/logger/lib/logger/utils.ex

+23-2
Original file line numberDiff line numberDiff line change
@@ -42,11 +42,32 @@ defmodule Logger.Utils do
4242
else
4343
:none -> :ignore
4444
:skip -> :stop
45-
{:ok, chardata} -> %{event | msg: {:string, chardata}}
46-
{:ok, char, meta} -> %{event | msg: {:string, char}, meta: Enum.into(meta, event.meta)}
45+
{:ok, chardata} -> return_translated_event(event, chardata)
46+
{:ok, char, meta} -> return_translated_event(event, char, meta)
4747
end
4848
end
4949

50+
def translated_cb(report) do
51+
{~c"~ts", [report[:elixir_translation]]}
52+
end
53+
54+
defp return_translated_event(event, translated, meta \\ [])
55+
56+
defp return_translated_event(%{msg: {:report, report}} = event, translated, meta) do
57+
report = Enum.into([elixir_translation: translated], report)
58+
meta = Enum.into(meta, event.meta)
59+
60+
%{
61+
event
62+
| msg: {:report, report},
63+
meta: Enum.into([report_cb: &__MODULE__.translated_cb/1], meta)
64+
}
65+
end
66+
67+
defp return_translated_event(event, translated, meta) do
68+
%{event | msg: {:string, translated}, meta: Enum.into(meta, event.meta)}
69+
end
70+
5071
defp translate([{mod, fun} | t], min_level, level, kind, data) do
5172
with :none <- apply(mod, fun, [min_level, level, kind, data]) do
5273
translate(t, min_level, level, kind, data)

‎lib/logger/test/logger/translator_test.exs

+60-52
Original file line numberDiff line numberDiff line change
@@ -183,8 +183,8 @@ defmodule Logger.TranslatorTest do
183183
** (RuntimeError) oops
184184
"""
185185

186-
assert_receive {:event, {:string, ["GenServer " <> _ | _]}, gen_server_metadata}
187-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
186+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, gen_server_metadata}
187+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
188188

189189
assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_server_metadata[:crash_reason]
190190
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
@@ -200,8 +200,8 @@ defmodule Logger.TranslatorTest do
200200
{:ok, pid} = GenServer.start(MyGenServer, :ok, name: config.test)
201201
capture_log(:info, fn -> catch_exit(GenServer.call(pid, :error)) end)
202202

203-
assert_receive {:event, {:string, ["GenServer " <> _ | _]}, gen_server_metadata}
204-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
203+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, gen_server_metadata}
204+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
205205

206206
assert gen_server_metadata[:registered_name] == config.test
207207
assert process_metadata[:registered_name] == config.test
@@ -211,8 +211,8 @@ defmodule Logger.TranslatorTest do
211211
{:ok, pid} = GenServer.start(MyGenServer, :ok, name: {:global, config.test})
212212
capture_log(:info, fn -> catch_exit(GenServer.call(pid, :error)) end)
213213

214-
assert_receive {:event, {:string, ["GenServer " <> _ | _]}, gen_server_metadata}
215-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
214+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, gen_server_metadata}
215+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
216216

217217
assert gen_server_metadata[:registered_name] == config.test
218218
refute Map.has_key?(process_metadata, :registered_name)
@@ -260,8 +260,8 @@ defmodule Logger.TranslatorTest do
260260
.*
261261
"""s
262262

263-
assert_receive {:event, {:string, [["GenServer " <> _ | _] | _]}, gen_server_metadata}
264-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
263+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, gen_server_metadata}
264+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
265265

266266
assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_server_metadata[:crash_reason]
267267
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
@@ -330,8 +330,8 @@ defmodule Logger.TranslatorTest do
330330
assert_receive {:DOWN, ^mon, _, _, _}
331331
end) =~ "Client"
332332

333-
assert_receive {:event, {:string, [["GenServer " <> _ | _] | _]}, _gen_server_metadata}
334-
assert_receive {:event, {:string, ["Process " | _]}, _process_metadata}
333+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, _gen_server_metadata}
334+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, _process_metadata}
335335
end
336336

337337
test "translates :gen_event crashes" do
@@ -346,7 +346,7 @@ defmodule Logger.TranslatorTest do
346346
** (RuntimeError) oops
347347
"""
348348

349-
assert_receive {:event, {:string, [":gen_event handler " <> _ | _]}, metadata}
349+
assert_receive {:event, {:report, %{label: {:gen_event, :terminate}}}, metadata}
350350
assert {%RuntimeError{message: "oops"}, [_ | _]} = metadata[:crash_reason]
351351
refute Map.has_key?(metadata, :initial_call)
352352
refute Map.has_key?(metadata, :registered_name)
@@ -364,7 +364,7 @@ defmodule Logger.TranslatorTest do
364364
** (RuntimeError) oops
365365
"""
366366

367-
assert_receive {:event, {:string, [":gen_event handler " <> _ | _]}, metadata}
367+
assert_receive {:event, {:report, %{label: {:gen_event, :terminate}}}, metadata}
368368
assert {%RuntimeError{message: "oops"}, [_ | _]} = metadata[:crash_reason]
369369
assert metadata[:registered_name] == config.test
370370
end
@@ -402,7 +402,7 @@ defmodule Logger.TranslatorTest do
402402
State: :ok
403403
"""s
404404

405-
assert_receive {:event, {:string, [[":gen_event handler " <> _ | _] | _]}, metadata}
405+
assert_receive {:event, {:report, %{label: {:gen_event, :terminate}}}, metadata}
406406
assert {%RuntimeError{message: "oops"}, [_ | _]} = metadata[:crash_reason]
407407
end
408408

@@ -416,8 +416,8 @@ defmodule Logger.TranslatorTest do
416416
** (RuntimeError) oops
417417
"""
418418

419-
assert_receive {:event, {:string, [":gen_statem " <> _ | _]}, gen_statem_metadata}
420-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
419+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, gen_statem_metadata}
420+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
421421

422422
assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_statem_metadata[:crash_reason]
423423
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
@@ -433,8 +433,8 @@ defmodule Logger.TranslatorTest do
433433
{:ok, pid} = :gen_statem.start({:local, config.test}, MyGenStatem, :ok, [])
434434
capture_log(:info, fn -> catch_exit(:gen_statem.call(pid, :error)) end)
435435

436-
assert_receive {:event, {:string, [":gen_statem " <> _ | _]}, gen_statem_metadata}
437-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
436+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, gen_statem_metadata}
437+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
438438

439439
assert gen_statem_metadata[:registered_name] == config.test
440440
assert process_metadata[:registered_name] == config.test
@@ -444,8 +444,8 @@ defmodule Logger.TranslatorTest do
444444
{:ok, pid} = :gen_statem.start({:global, config.test}, MyGenStatem, :ok, [])
445445
capture_log(:info, fn -> catch_exit(:gen_statem.call(pid, :error)) end)
446446

447-
assert_receive {:event, {:string, [":gen_statem " <> _ | _]}, gen_statem_metadata}
448-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
447+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, gen_statem_metadata}
448+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
449449

450450
assert gen_statem_metadata[:registered_name] == config.test
451451
refute Map.has_key?(process_metadata, :registered_name)
@@ -498,8 +498,8 @@ defmodule Logger.TranslatorTest do
498498
.*
499499
"""s
500500

501-
assert_receive {:event, {:string, [[":gen_statem " <> _ | _] | _]}, gen_statem_metadata}
502-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
501+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, gen_statem_metadata}
502+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
503503

504504
assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_statem_metadata[:crash_reason]
505505
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
@@ -574,8 +574,8 @@ defmodule Logger.TranslatorTest do
574574
assert_receive {:DOWN, ^mon, _, _, _}
575575
end) =~ "Client"
576576

577-
assert_receive {:event, {:string, [[":gen_statem " <> _ | _] | _]}, _gen_statem_metadata}
578-
assert_receive {:event, {:string, ["Process " | _]}, _process_metadata}
577+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, _gen_statem_metadata}
578+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, _process_metadata}
579579
end
580580

581581
test "translates :gen_statem crashes when callback_mode is :handle_event_function" do
@@ -593,8 +593,8 @@ defmodule Logger.TranslatorTest do
593593
Callback mode: .*, state_enter: false
594594
"""s
595595

596-
assert_receive {:event, {:string, [[":gen_statem " <> _ | _] | _]}, gen_statem_metadata}
597-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
596+
assert_receive {:event, {:report, %{label: {:gen_statem, :terminate}}}, gen_statem_metadata}
597+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
598598

599599
assert {%RuntimeError{message: "oops"}, [_ | _]} = gen_statem_metadata[:crash_reason]
600600
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
@@ -622,7 +622,7 @@ defmodule Logger.TranslatorTest do
622622
Args: \[#PID<\d+\.\d+\.\d+>\]
623623
"""s
624624

625-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
625+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
626626
assert {%RuntimeError{message: "oops"}, [_ | _]} = task_metadata[:crash_reason]
627627
assert [parent] == task_metadata[:callers]
628628
refute Map.has_key?(task_metadata, :initial_call)
@@ -643,7 +643,7 @@ defmodule Logger.TranslatorTest do
643643
Args: \[\]
644644
"""s
645645

646-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
646+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
647647
assert [parent] == task_metadata[:callers]
648648
assert {%UndefinedFunctionError{function: :undef}, [_ | _]} = task_metadata[:crash_reason]
649649
end
@@ -663,7 +663,7 @@ defmodule Logger.TranslatorTest do
663663
Args: \[\]
664664
"""s
665665

666-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
666+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
667667
assert [parent] == task_metadata[:callers]
668668
assert {%UndefinedFunctionError{function: :undef}, [_ | _]} = task_metadata[:crash_reason]
669669
end
@@ -691,7 +691,7 @@ defmodule Logger.TranslatorTest do
691691
Args: \[%ErlangError{.*}\]
692692
"""s
693693

694-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
694+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
695695
assert [parent] == task_metadata[:callers]
696696
assert {%ErlangError{original: :foo}, [_ | _]} = task_metadata[:crash_reason]
697697
end
@@ -711,7 +711,7 @@ defmodule Logger.TranslatorTest do
711711
Args: \[:badarg\]
712712
"""s
713713

714-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
714+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
715715
assert [parent] == task_metadata[:callers]
716716
assert {%ArgumentError{message: "argument error"}, [_ | _]} = task_metadata[:crash_reason]
717717
end
@@ -731,7 +731,7 @@ defmodule Logger.TranslatorTest do
731731
Args: \[:abnormal\]
732732
"""s
733733

734-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
734+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
735735
assert [parent] == task_metadata[:callers]
736736
assert {:abnormal, [_ | _]} = task_metadata[:crash_reason]
737737
end
@@ -813,7 +813,7 @@ defmodule Logger.TranslatorTest do
813813
Ancestors: \[#PID<\d+\.\d+\.\d+>\]
814814
"""s
815815

816-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
816+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
817817

818818
assert is_pid(process_metadata[:pid])
819819
assert is_list(process_metadata[:ancestors])
@@ -857,7 +857,7 @@ defmodule Logger.TranslatorTest do
857857
Ancestors: \[#PID<\d+\.\d+\.\d+>\]
858858
"""s
859859

860-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
860+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
861861
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
862862
end
863863

@@ -884,7 +884,7 @@ defmodule Logger.TranslatorTest do
884884
Ancestors: \[#PID<\d+\.\d+\.\d+>\]
885885
"""s
886886

887-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
887+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
888888
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
889889
end
890890

@@ -908,7 +908,7 @@ defmodule Logger.TranslatorTest do
908908
Ancestors: \[#PID<\d+\.\d+\.\d+>\]
909909
"""s
910910

911-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
911+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
912912
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]
913913
end
914914

@@ -1051,7 +1051,7 @@ defmodule Logger.TranslatorTest do
10511051
Start Call: Logger.TranslatorTest.undef\(\)
10521052
"""s
10531053

1054-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1054+
assert_receive {:event, {:report, %{label: {:supervisor, :start_error}}}, _child_metadata}
10551055
end
10561056

10571057
test "translates Supervisor reports terminated" do
@@ -1068,9 +1068,12 @@ defmodule Logger.TranslatorTest do
10681068
Start Call: Task.start_link\(Kernel, :exit, \[:stop\]\)
10691069
"""
10701070

1071-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
1072-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1073-
assert_receive {:event, {:string, ["Child ", "Task" | _]}, _child_task_metadata}
1071+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
1072+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown}}}, _child_metadata}
1073+
1074+
assert_receive {:event, {:report, %{label: {:supervisor, :child_terminated}}},
1075+
_child_task_metadata}
1076+
10741077
assert {:stop, [_ | _]} = task_metadata[:crash_reason]
10751078
end
10761079

@@ -1087,9 +1090,12 @@ defmodule Logger.TranslatorTest do
10871090
Start Call: Task.start_link\(Kernel, :exit, \[:stop\]\)
10881091
"""
10891092

1090-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
1091-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1092-
assert_receive {:event, {:string, ["Child ", "Task" | _]}, _child_task_metadata}
1093+
assert_receive {:event, {:report, %{label: {Task.Supervisor, :terminating}}}, task_metadata}
1094+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown}}}, _child_metadata}
1095+
1096+
assert_receive {:event, {:report, %{label: {:supervisor, :child_terminated}}},
1097+
_child_task_metadata}
1098+
10931099
assert {:stop, [_ | _]} = task_metadata[:crash_reason]
10941100
end
10951101

@@ -1105,7 +1111,7 @@ defmodule Logger.TranslatorTest do
11051111
Start Call: Logger.TranslatorTest.abnormal\(\)
11061112
"""
11071113

1108-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1114+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown_error}}}, _child_metadata}
11091115
end
11101116

11111117
test "translates Supervisor reports abnormal shutdown on debug" do
@@ -1125,7 +1131,7 @@ defmodule Logger.TranslatorTest do
11251131
Type: :worker
11261132
"""
11271133

1128-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1134+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown_error}}}, _child_metadata}
11291135
end
11301136

11311137
test "translates DynamicSupervisor reports abnormal shutdown" do
@@ -1144,7 +1150,7 @@ defmodule Logger.TranslatorTest do
11441150
Start Call: Logger.TranslatorTest.abnormal\(\)
11451151
"""
11461152

1147-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1153+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown_error}}}, _child_metadata}
11481154
end
11491155

11501156
test "translates DynamicSupervisor reports abnormal shutdown including extra_arguments" do
@@ -1165,7 +1171,7 @@ defmodule Logger.TranslatorTest do
11651171
Start Call: Logger.TranslatorTest.abnormal\(:extra, :args\)
11661172
"""
11671173

1168-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1174+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown_error}}}, _child_metadata}
11691175
end
11701176

11711177
test "translates named DynamicSupervisor reports abnormal shutdown" do
@@ -1184,7 +1190,7 @@ defmodule Logger.TranslatorTest do
11841190
Start Call: Logger.TranslatorTest.abnormal\(\)
11851191
"""
11861192

1187-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1193+
assert_receive {:event, {:report, %{label: {:supervisor, :shutdown_error}}}, _child_metadata}
11881194
end
11891195

11901196
test "translates :supervisor_bridge progress" do
@@ -1213,8 +1219,8 @@ defmodule Logger.TranslatorTest do
12131219
Start Module: Logger.TranslatorTest.MyBridge
12141220
"""
12151221

1216-
assert_receive {:event, {:string, ["Task " <> _ | _]}, task_metadata}
1217-
assert_receive {:event, {:string, ["Child of Supervisor " | _]}, _child_metadata}
1222+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, task_metadata}
1223+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, _child_metadata}
12181224
assert {:stop, [_ | _]} = task_metadata[:crash_reason]
12191225
end
12201226

@@ -1252,9 +1258,11 @@ defmodule Logger.TranslatorTest do
12521258
end)
12531259

12541260
assert log =~ ~s(Start Call: Logger.TranslatorTest.WeirdFunctionNamesGenServer."start link"/?)
1255-
assert_receive {:event, {:string, ["GenServer " <> _ | _]}, server_metadata}
1256-
assert_receive {:event, {:string, ["Process " | _]}, process_metadata}
1257-
assert_receive {:event, {:string, ["Child " | _]}, _child_metadata}
1261+
assert_receive {:event, {:report, %{label: {:gen_server, :terminate}}}, server_metadata}
1262+
assert_receive {:event, {:report, %{label: {:proc_lib, :crash}}}, process_metadata}
1263+
1264+
assert_receive {:event, {:report, %{label: {:supervisor, :child_terminated}}},
1265+
_child_metadata}
12581266

12591267
assert {%RuntimeError{message: "oops"}, [_ | _]} = server_metadata[:crash_reason]
12601268
assert {%RuntimeError{message: "oops"}, [_ | _]} = process_metadata[:crash_reason]

0 commit comments

Comments
 (0)