1: -module(json_formatter_SUITE).
2:
3: -export([all/0, init_per_testcase/2, end_per_testcase/2]).
4:
5: -export([
6: something_is_logged/1,
7: something_is_formatted/1,
8: acc_is_formatted/1,
9: acc_is_preserved/1,
10: chars_limited/1,
11: format_depth_limited/1,
12: json_depth_limited/1,
13: large_event_dont_crash_formatter/1
14: ]).
15:
16: -import(logger_helper, [filter_out_non_matching/2, get_at_least_n_log_lines/3, get_log/1]).
17:
18: -include_lib("kernel/include/logger.hrl").
19: -include_lib("common_test/include/ct.hrl").
20: -include_lib("eunit/include/eunit.hrl").
21:
22: -define(LOGFILE, "log/mongooseim.log").
23: -define(HID, json_log).
24:
25: all() ->
26: [
27: something_is_logged,
28: something_is_formatted,
29: acc_is_formatted,
30: acc_is_preserved,
31: chars_limited,
32: format_depth_limited,
33: json_depth_limited,
34: large_event_dont_crash_formatter
35: ].
36:
37: init_per_testcase(acc_is_preserved, Config) ->
38: LoggerConfig = logger:get_primary_config(),
39: logger:set_primary_config(level, info),
40: ConfigFilters = #{filters =>
41: [{preserve_acc_filter, {fun mongoose_log_filter:preserve_acc_filter/2, no_state}},
42: {format_packet_filter, {fun mongoose_log_filter:format_packet_filter/2, no_state}},
43: {format_acc_filter, {fun mongoose_log_filter:format_acc_filter/2, no_state}},
44: {format_c2s_state_filter, {fun mongoose_log_filter:format_c2s_state_filter/2, no_state}},
45: {format_stacktrace_filter, {fun mongoose_log_filter:format_stacktrace_filter/2, no_state}}
46: ]},
47: {ok, Backend} = mongoose_logger_running(ConfigFilters),
48: [{logger_primary_config, LoggerConfig}, {logger_backend, Backend} | Config];
49: init_per_testcase(format_depth_limited, Config) ->
50: LoggerConfig = logger:get_primary_config(),
51: logger:set_primary_config(level, info),
52: DepthLimit = 2,
53: ConfigFormatter = #{formatter => {mongoose_json_formatter, #{format_depth => DepthLimit}}},
54: {ok, Backend} = mongoose_logger_running(ConfigFormatter),
55: [{logger_primary_config, LoggerConfig}, {logger_backend, Backend}, {format_depth, DepthLimit}| Config];
56: init_per_testcase(chars_limited, Config) ->
57: LoggerConfig = logger:get_primary_config(),
58: logger:set_primary_config(level, info),
59: CharsLimit = 30,
60: ConfigFormatter = #{formatter => {mongoose_json_formatter, #{format_chars_limit => CharsLimit}}},
61: {ok, Backend} = mongoose_logger_running(ConfigFormatter),
62: [{logger_primary_config, LoggerConfig}, {logger_backend, Backend}, {chars_limit, CharsLimit}| Config];
63: init_per_testcase(json_depth_limited, Config) ->
64: LoggerConfig = logger:get_primary_config(),
65: logger:set_primary_config(level, info),
66: Depth = 5,
67: ConfigFormatter = #{formatter => {mongoose_json_formatter, #{depth => Depth}}},
68: {ok, Backend} = mongoose_logger_running(ConfigFormatter),
69: [{logger_primary_config, LoggerConfig}, {logger_backend, Backend}, {depth, Depth}| Config];
70: init_per_testcase(_TC, Config) ->
71: LoggerConfig = logger:get_primary_config(),
72: logger:set_primary_config(level, info),
73: {ok, Backend} = mongoose_logger_running(),
74: [{logger_primary_config, LoggerConfig}, {logger_backend, Backend} | Config].
75:
76: end_per_testcase(_TC, Config) ->
77: logger:remove_handler(?HID),
78: logger:set_primary_config(?config(logger_primary_config, Config)),
79: ok.
80:
81: %%
82: %% Tests
83: %%
84: something_is_logged(Config) ->
85: {_, File} = ?config(logger_backend, Config),
86: Before = get_log(File),
87: ?LOG_INFO(#{what => something_is_logged,
88: text => "JSON formatter test. This is an example message.",
89: code => 404, reason => test_execution}),
90: ?assertNotEqual(timeout, get_at_least_n_log_lines(File, length(Before) + 1, timer:seconds(5))).
91:
92: something_is_formatted(Config) ->
93: {_, File} = ?config(logger_backend, Config),
94: Before = get_log(File),
95:
96: ?LOG_INFO(#{in => config, user => #{name => <<"bbby">>, id => 12345}, details => {entropy, too_low},
97: txt => <<"JSON formatter test. JSON-match-this-something">>}),
98:
99: After = case get_at_least_n_log_lines(?LOGFILE,
100: length(Before) + 1,
101: timer:seconds(1)) of
102: timeout -> ct:fail("timed out waiting for messages to reach the log file");
103: Res -> Res
104: end,
105:
106: [Line] = filter_out_non_matching(After -- Before, <<"JSON-match-this-something">>),
107: Decoded = jiffy:decode(Line, [return_maps]),
108:
109: #{<<"level">> := <<"info">>,
110: <<"when">> := DateTimeStrBin,
111: <<"meta">> := #{<<"file">> := _File,
112: <<"line">> := _Line,
113: <<"mfa">> := <<"{json_formatter_SUITE,something_is_formatted,1}">>,
114: <<"pid">> := Pid},
115: <<"details">> := <<"{entropy,too_low}">>,
116: <<"in">> := <<"config">>,
117: <<"txt">> := <<"JSON formatter test. JSON-match-this-something">>,
118: <<"user">> := #{<<"id">> := <<"12345">>,
119: <<"name">> := <<"bbby">>}}
120: = Decoded,
121:
122: ?assert(is_integer(calendar:rfc3339_to_system_time(binary_to_list(DateTimeStrBin)))),
123: Pid = unicode:characters_to_binary(pid_to_list(self())).
124:
125: acc_is_formatted(Config) ->
126: {_, File} = ?config(logger_backend, Config),
127: Before = get_log(File),
128:
129: Body = <<"JSON-match-this-acc">>,
130: Acc = example_acc(Body),
131:
132: ?LOG_INFO(#{what => routing_result, acc => Acc, routing_modules => [mongoose_router_1, mongoose_router_2],
133: routing_result => [{{inside, two_tuples}}, {inside, one_tuple}]}),
134:
135: After = case get_at_least_n_log_lines(?LOGFILE,
136: length(Before) + 1,
137: timer:seconds(1)) of
138: timeout -> ct:fail("timed out waiting for messages to reach the log file");
139: Res -> Res
140: end,
141:
142: [Line] = filter_out_non_matching(After -- Before, Body),
143:
144: Decoded = jiffy:decode(Line, [return_maps]),
145:
146: #{<<"level">> := <<"info">>,
147: <<"when">> := DateTimeStrBin,
148: <<"meta">> := #{<<"file">> := _File,
149: <<"line">> := _Line,
150: <<"mfa">> := <<"{json_formatter_SUITE,acc_is_formatted,1}">>,
151: <<"pid">> := Pid},
152: % Because of the format_acc_filter/2 we don't get the full accumulator
153: <<"acc_timestamp">> := DateTimeStrBin2,
154: <<"from_jid">> := <<"usera@localhost">>,
155: <<"origin_pid">> := Pid,
156: % format_packet_filter/2 changes the packet
157: <<"packet">> := <<"<message type='chat' id='1111'><body>JSON-match-this-acc</body></message>">>,
158: <<"routing_modules">> := [<<"mongoose_router_1">>, <<"mongoose_router_2">>],
159: <<"routing_result">> := [<<"{{inside,two_tuples}}">>,<<"{inside,one_tuple}">>],
160: <<"to_jid">> := <<"userb@localhost">>,
161: <<"what">> := <<"routing_result">>} = Decoded,
162:
163: ?assert(is_integer(calendar:rfc3339_to_system_time(binary_to_list(DateTimeStrBin)))),
164: ?assert(is_integer(calendar:rfc3339_to_system_time(binary_to_list(DateTimeStrBin2)))),
165: Pid = unicode:characters_to_binary(pid_to_list(self())).
166:
167: acc_is_preserved(Config) ->
168: ok = logger:add_primary_filter(preserve_acc_filter, {fun mongoose_log_filter:preserve_acc_filter/2, no_state}),
169:
170: {_, File} = ?config(logger_backend, Config),
171: Before = get_log(File),
172:
173: Body = <<"JSON-match-this-preserve-acc">>,
174: Acc = example_acc(Body),
175:
176: ?LOG_INFO(#{what => routing_result, acc => Acc, routing_modules => [mongoose_router_1, mongoose_router_2],
177: routing_result => [{{inside, two_tuples}}, {inside, one_tuple}]}),
178:
179: After = case get_at_least_n_log_lines(?LOGFILE,
180: length(Before) + 1,
181: timer:seconds(1)) of
182: timeout -> ct:fail("timed out waiting for messages to reach the log file");
183: Res -> Res
184: end,
185:
186: [Line] = filter_out_non_matching(After -- Before, Body),
187:
188: Decoded = jiffy:decode(Line, [return_maps]),
189:
190: #{<<"level">> := <<"info">>,
191: <<"when">> := DateTimeStrBin,
192: <<"meta">> := #{<<"file">> := _File,
193: <<"line">> := _Line,
194: <<"mfa">> := <<"{json_formatter_SUITE,acc_is_preserved,1}">>,
195: <<"pid">> := Pid},
196: % Because of the preserve_acc_filter/2 we get the full accumulator as acc_original
197: <<"acc_original">> := A,
198: <<"acc_timestamp">> := DateTimeStrBin2,
199: <<"from_jid">> := <<"usera@localhost">>,
200: <<"origin_pid">> := Pid,
201: % format_packet_filter/2 changes the packet
202: <<"packet">> := <<"<message type='chat' id='1111'><body>JSON-match-this-preserve-acc</body></message>">>,
203: <<"routing_modules">> := [<<"mongoose_router_1">>, <<"mongoose_router_2">>],
204: <<"routing_result">> := [<<"{{inside,two_tuples}}">>,<<"{inside,one_tuple}">>],
205: <<"to_jid">> := <<"userb@localhost">>,
206: <<"what">> := <<"routing_result">>} = Decoded,
207:
208: % This is not ideal but that's how the filter behaves
209: A = iolist_to_binary(io_lib:format("~0p", [Acc])),
210:
211: ?assert(is_integer(calendar:rfc3339_to_system_time(binary_to_list(DateTimeStrBin)))),
212: ?assert(is_integer(calendar:rfc3339_to_system_time(binary_to_list(DateTimeStrBin2)))),
213: Pid = unicode:characters_to_binary(pid_to_list(self())).
214:
215: chars_limited(Config) ->
216:
217: {_, File} = ?config(logger_backend, Config),
218: Before = get_log(File),
219: CharsLimit = ?config(chars_limit, Config),
220:
221: LongBinary = unicode:characters_to_binary([<<"a">> || _ <- lists:seq(1, CharsLimit*2)]),
222: LongText = unicode:characters_to_list(["a" || _ <- lists:seq(1, CharsLimit*2)]),
223: LongStruct = {["a" || _ <- lists:seq(1, CharsLimit*2)]},
224:
225: ?LOG_INFO(#{what => chars_are_limited,
226: text => "JSON-match-this-chars-limited",
227: long_binary => LongBinary,
228: long_text => LongText,
229: long_struct => LongStruct}),
230:
231: After = case get_at_least_n_log_lines(?LOGFILE,
232: length(Before) + 1,
233: timer:seconds(1)) of
234: timeout -> ct:fail("timed out waiting for messages to reach the log file");
235: Res -> Res
236: end,
237:
238: [Line] = filter_out_non_matching(After -- Before, <<"JSON-match-this-chars-limited">>),
239:
240: Decoded = jiffy:decode(Line, [return_maps]),
241:
242: ShortenedBinary = binary_part(LongBinary, 0, CharsLimit),
243: ShortenedText = binary_part(unicode:characters_to_binary(LongText, utf8), 0, CharsLimit),
244: ShortenedStruct = unicode:characters_to_binary(io_lib:format("~0p", [LongStruct], [{chars_limit, CharsLimit}])),
245:
246: ?assertMatch(#{<<"level">> := <<"info">>,
247: <<"when">> := _Time,
248: <<"meta">> := #{<<"file">> := _File,
249: <<"line">> := _Line,
250: <<"mfa">> := _MFA,
251: <<"pid">> := _Pid},
252: <<"what">> := <<"chars_are_limited">>,
253: <<"text">> := <<"JSON-match-this-chars-limited">>,
254: <<"long_binary">> := ShortenedBinary,
255: <<"long_text">> := ShortenedText,
256: <<"long_struct">> := ShortenedStruct},
257: Decoded).
258:
259: format_depth_limited(Config) ->
260:
261: {_, File} = ?config(logger_backend, Config),
262: Before = get_log(File),
263:
264: FormatDepth = ?config(format_depth, Config),
265: DeepStruct = deep_tuple(FormatDepth*2),
266:
267: ?LOG_INFO(#{what => format_depth_limited,
268: text => "JSON-match-this-struct-depth-limited",
269: deep_struct => DeepStruct}),
270:
271: After = case get_at_least_n_log_lines(?LOGFILE,
272: length(Before) + 1,
273: timer:seconds(1)) of
274: timeout -> ct:fail("timed out waiting for messages to reach the log file");
275: Res -> Res
276: end,
277:
278: [Line] = filter_out_non_matching(After -- Before, <<"JSON-match-this-struct-depth-limited">>),
279:
280: Decoded = jiffy:decode(Line, [return_maps]),
281:
282: ShortenedStruct = unicode:characters_to_binary(io_lib:format("~0P", [DeepStruct, FormatDepth])),
283:
284: ?assertMatch(#{<<"level">> := <<"info">>,
285: <<"when">> := _Time,
286: <<"meta">> := #{<<"file">> := _File,
287: <<"line">> := _Line,
288: <<"mfa">> := _MFA,
289: <<"pid">> := _Pid},
290: <<"what">> := <<"format_depth_limited">>,
291: <<"text">> := <<"JSON-match-this-struct-depth-limited">>,
292: <<"deep_struct">> := ShortenedStruct},
293: Decoded).
294:
295:
296: json_depth_limited(Config) ->
297:
298: {_, File} = ?config(logger_backend, Config),
299: Before = get_log(File),
300:
301: Depth = ?config(depth, Config),
302: DeepList = deep_list(Depth*2),
303:
304: ?LOG_INFO(#{what => json_depth_limited,
305: text => "JSON-match-this-json-depth-limited",
306: deep_list => DeepList}),
307:
308: After = case get_at_least_n_log_lines(?LOGFILE,
309: length(Before) + 1,
310: timer:seconds(1)) of
311: timeout -> ct:fail("timed out waiting for messages to reach the log file");
312: Res -> Res
313: end,
314:
315: [Line] = filter_out_non_matching(After -- Before, <<"JSON-match-this-json-depth-limited">>),
316:
317: Decoded = jiffy:decode(Line, [return_maps]),
318:
319: % 1 because it is at the first level
320: ShortenedList = deep_list(Depth - 1, <<"...">>),
321:
322: ?assertMatch(#{<<"level">> := <<"info">>,
323: <<"when">> := _Time,
324: <<"meta">> := #{<<"file">> := _File,
325: <<"line">> := _Line,
326: <<"mfa">> := _MFA,
327: <<"pid">> := _Pid},
328: <<"what">> := <<"json_depth_limited">>,
329: <<"text">> := <<"JSON-match-this-json-depth-limited">>,
330: <<"deep_list">> := ShortenedList},
331: Decoded).
332:
333: large_event_dont_crash_formatter(_Config) ->
334:
335: ?LOG_INFO(#{what => large_log,
336: large_log_msg => large_log_msg()}),
337:
338: DidFormatterCrash = is_in_file(?LOGFILE,
339: "[0-9\\+\\-T:\\.]* info: FORMATTER CRASH: .*",
340: timer:seconds(1)),
341:
342: ?assertMatch(DidFormatterCrash, false).
343:
344: %%
345: %% Helpers
346: %%
347:
348: example_acc(Body) ->
349: Elem = {xmlel, <<"message">>,
350: [{<<"type">>, <<"chat">>}, {<<"id">>, <<"1111">>}],
351: [{xmlel, <<"body">>, [], [{xmlcdata, Body}]}]},
352: #{lserver => <<"localhost">>,
353: mongoose_acc => true,
354: non_strippable => [],
355: origin_location => #{file => "/Users/user/MongooseIM/src/ejabberd_router.erl",
356: line => 116,
357: mfa => {ejabberd_router,route,3}},
358: origin_pid => self(),
359: ref => make_ref(),
360: stanza => #{element => Elem,
361: from_jid => {jid, <<"usera">>, <<"localhost">>, <<>>},
362: name => <<"message">>,
363: ref => make_ref(),
364: to_jid => {jid, <<"userb">>, <<"localhost">>, <<>>},
365: type => <<"chat">>},
366: timestamp => 1598878576962100}.
367:
368: mongoose_logger_running() ->
369: mongoose_logger_running(#{}).
370: mongoose_logger_running(HandlerConfig) ->
371: HandlerID = ?HID,
372: HandlerModule = logger_std_h,
373: DefaultConfig = #{level => info,
374: config => #{file => ?LOGFILE},
375: formatter => {mongoose_json_formatter, #{}},
376: filters => [
377: {format_packet_filter, {fun mongoose_log_filter:format_packet_filter/2, no_state}},
378: {format_acc_filter, {fun mongoose_log_filter:format_acc_filter/2, no_state}},
379: {format_c2s_state_filter, {fun mongoose_log_filter:format_c2s_state_filter/2, no_state}},
380: {format_stacktrace_filter, {fun mongoose_log_filter:format_stacktrace_filter/2, no_state}}
381: ]
382: },
383: Config = maps:merge(DefaultConfig, HandlerConfig),
384: ok = logger:add_handler(HandlerID, HandlerModule, Config),
385: FileBackend = {HandlerID, ?LOGFILE},
386: {ok, FileBackend}.
387:
388: deep_tuple(1) ->
389: {"a"};
390: deep_tuple(N) ->
391: {deep_tuple(N-1)}.
392:
393: deep_list(N) ->
394: deep_list(N, "a").
395: deep_list(1, Content) ->
396: [Content];
397: deep_list(N, Content) ->
398: [deep_list(N-1, Content)].
399:
400: is_in_file(FileName, Pattern, Time) when Time > 0 ->
401: case file:read_file(FileName) of
402: {ok, Bin} ->
403: case re:run(Bin,Pattern,[{capture,none}]) of
404: match ->
405: true;
406: _ ->
407: timer:sleep(100),
408: is_in_file(FileName, Pattern, Time-100)
409: end;
410: Error ->
411: erlang:error(Error)
412: end;
413: is_in_file(_FileName, _Pattern, _Time) ->
414: false.
415:
416: large_log_msg() ->
417: "These violent delights have violent ends " ++
418: "And in their triumph die, like fire and powder, " ++
419: "Which, as they kiss, consume. The sweetest honey" ++
420: "Is loathsome in his own deliciousness " ++
421: "And in the taste confounds the appetite. " ++
422: "Therefore love moderately: long love doth so; " ++
423: "Too swift arrives as tardy as too slow. " ++
424: "Rom. In faith, I will. Let me peruse this face. " ++
425: "Mercutio's kinsman, noble County Paris! " ++
426: "What said my man when my betossed soul " ++
427: "Did not attend him as we rode? I think " ++
428: "He told me Paris should have married Juliet. " ++
429: "Said he not so? or did I dream it so? " ++
430: "Or am I mad, hearing him talk of Juliet " ++
431: "To think it was so? O, give me thy hand, " ++
432: "One writ with me in sour misfortune's book! " ++
433: "I'll bury thee in a triumphant grave. " ++
434: "A grave? O, no, a lanthorn, slaught'red youth, " ++
435: "For here lies Juliet, and her beauty makes " ++
436: "This vault a feasting presence full of light. " ++
437: "Death, lie thou there, by a dead man interr'd. " ++
438: " [Lays him in the tomb.]" ++
439: "How oft when men are at the point of death " ++
440: "Have they been merry! which their keepers call " ++
441: "A lightning before death. O, how may I " ++
442: "Call this a lightning? O my love! my wife! " ++
443: "Death, that hath suck'd the honey of thy breath," ++
444: "Hath had no power yet upon thy beauty. " ++
445: "Thou art not conquer'd. Beauty's ensign yet " ++
446: "Is crimson in thy lips and in thy cheeks, " ++
447: "And death's pale flag is not advanced there. " ++
448: "Tybalt, liest thou there in thy bloody sheet? " ++
449: "O, what more favour can I do to thee " ++
450: "Than with that hand that cut thy youth in twain " ++
451: "To sunder his that was thine enemy? " ++
452: "Forgive me, cousin.' Ah, dear Juliet, " ++
453: "Why art thou yet so fair? Shall I believe " ++
454: "That unsubstantial Death is amorous, " ++
455: "And that the lean abhorred monster keeps " ++
456: "Thee here in dark to be his paramour? " ++
457: "For fear of that I still will stay with thee " ++
458: "And never from this palace of dim night " ++
459: "Depart again. Here, here will I remain " ++
460: "With worms that are thy chambermaids. O, here " ++
461: "Will I set up my everlasting rest " ++
462: "And shake the yoke of inauspicious stars " ++
463: "From this world-wearied flesh. Eyes, look your last!" ++
464: "Arms, take your last embrace! and, lips, O you " ++
465: "The doors of breath, seal with a righteous kiss " ++
466: "A dateless bargain to engrossing death! " ++
467: "Come, bitter conduct; come, unsavoury guide! " ++
468: "Thou desperate pilot, now at once run on " ++
469: "The dashing rocks thy seasick weary bark! " ++
470: "Here's to my love! [Drinks.] O true apothecary! " ++
471: "Thy drugs are quick. Thus with a kiss I die.".