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: #{lserver => <<"localhost">>, 350: mongoose_acc => true, 351: non_strippable => [], 352: origin_location => #{file => "/Users/user/MongooseIM/src/ejabberd_router.erl", 353: line => 116, 354: mfa => {ejabberd_router,route,3}}, 355: origin_pid => self(), 356: origin_stanza => <<"<message type='chat' id='1111'><body>", 357: Body/binary, 358: "</body></message>">>, 359: ref => make_ref(), 360: stanza => #{element => {xmlel,<<"message">>, 361: [{<<"type">>,<<"chat">>},{<<"id">>,<<"1111">>}], 362: [{xmlel,<<"body">>,[], 363: [{xmlcdata,Body}]}]}, 364: from_jid => {jid,<<"userA">>,<<"localhost">>,<<>>,<<"usera">>,<<"localhost">>,<<>>}, 365: name => <<"message">>, 366: ref => make_ref(), 367: to_jid => {jid,<<"userB">>,<<"localhost">>,<<>>,<<"userb">>,<<"localhost">>,<<>>}, 368: type => <<"chat">>}, 369: timestamp => 1598878576962100}. 370: 371: mongoose_logger_running() -> 372: mongoose_logger_running(#{}). 373: mongoose_logger_running(HandlerConfig) -> 374: HandlerID = ?HID, 375: HandlerModule = logger_std_h, 376: DefaultConfig = #{level => info, 377: config => #{file => ?LOGFILE}, 378: formatter => {mongoose_json_formatter, #{}}, 379: filters => [ 380: {format_packet_filter, {fun mongoose_log_filter:format_packet_filter/2, no_state}}, 381: {format_acc_filter, {fun mongoose_log_filter:format_acc_filter/2, no_state}}, 382: {format_c2s_state_filter, {fun mongoose_log_filter:format_c2s_state_filter/2, no_state}}, 383: {format_stacktrace_filter, {fun mongoose_log_filter:format_stacktrace_filter/2, no_state}} 384: ] 385: }, 386: Config = maps:merge(DefaultConfig, HandlerConfig), 387: ok = logger:add_handler(HandlerID, HandlerModule, Config), 388: FileBackend = {HandlerID, ?LOGFILE}, 389: {ok, FileBackend}. 390: 391: deep_tuple(1) -> 392: {"a"}; 393: deep_tuple(N) -> 394: {deep_tuple(N-1)}. 395: 396: deep_list(N) -> 397: deep_list(N, "a"). 398: deep_list(1, Content) -> 399: [Content]; 400: deep_list(N, Content) -> 401: [deep_list(N-1, Content)]. 402: 403: is_in_file(FileName, Pattern, Time) when Time > 0 -> 404: case file:read_file(FileName) of 405: {ok, Bin} -> 406: case re:run(Bin,Pattern,[{capture,none}]) of 407: match -> 408: true; 409: _ -> 410: timer:sleep(100), 411: is_in_file(FileName, Pattern, Time-100) 412: end; 413: Error -> 414: erlang:error(Error) 415: end; 416: is_in_file(_FileName, _Pattern, _Time) -> 417: false. 418: 419: large_log_msg() -> 420: "These violent delights have violent ends " ++ 421: "And in their triumph die, like fire and powder, " ++ 422: "Which, as they kiss, consume. The sweetest honey" ++ 423: "Is loathsome in his own deliciousness " ++ 424: "And in the taste confounds the appetite. " ++ 425: "Therefore love moderately: long love doth so; " ++ 426: "Too swift arrives as tardy as too slow. " ++ 427: "Rom. In faith, I will. Let me peruse this face. " ++ 428: "Mercutio's kinsman, noble County Paris! " ++ 429: "What said my man when my betossed soul " ++ 430: "Did not attend him as we rode? I think " ++ 431: "He told me Paris should have married Juliet. " ++ 432: "Said he not so? or did I dream it so? " ++ 433: "Or am I mad, hearing him talk of Juliet " ++ 434: "To think it was so? O, give me thy hand, " ++ 435: "One writ with me in sour misfortune's book! " ++ 436: "I'll bury thee in a triumphant grave. " ++ 437: "A grave? O, no, a lanthorn, slaught'red youth, " ++ 438: "For here lies Juliet, and her beauty makes " ++ 439: "This vault a feasting presence full of light. " ++ 440: "Death, lie thou there, by a dead man interr'd. " ++ 441: " [Lays him in the tomb.]" ++ 442: "How oft when men are at the point of death " ++ 443: "Have they been merry! which their keepers call " ++ 444: "A lightning before death. O, how may I " ++ 445: "Call this a lightning? O my love! my wife! " ++ 446: "Death, that hath suck'd the honey of thy breath," ++ 447: "Hath had no power yet upon thy beauty. " ++ 448: "Thou art not conquer'd. Beauty's ensign yet " ++ 449: "Is crimson in thy lips and in thy cheeks, " ++ 450: "And death's pale flag is not advanced there. " ++ 451: "Tybalt, liest thou there in thy bloody sheet? " ++ 452: "O, what more favour can I do to thee " ++ 453: "Than with that hand that cut thy youth in twain " ++ 454: "To sunder his that was thine enemy? " ++ 455: "Forgive me, cousin.' Ah, dear Juliet, " ++ 456: "Why art thou yet so fair? Shall I believe " ++ 457: "That unsubstantial Death is amorous, " ++ 458: "And that the lean abhorred monster keeps " ++ 459: "Thee here in dark to be his paramour? " ++ 460: "For fear of that I still will stay with thee " ++ 461: "And never from this palace of dim night " ++ 462: "Depart again. Here, here will I remain " ++ 463: "With worms that are thy chambermaids. O, here " ++ 464: "Will I set up my everlasting rest " ++ 465: "And shake the yoke of inauspicious stars " ++ 466: "From this world-wearied flesh. Eyes, look your last!" ++ 467: "Arms, take your last embrace! and, lips, O you " ++ 468: "The doors of breath, seal with a righteous kiss " ++ 469: "A dateless bargain to engrossing death! " ++ 470: "Come, bitter conduct; come, unsavoury guide! " ++ 471: "Thou desperate pilot, now at once run on " ++ 472: "The dashing rocks thy seasick weary bark! " ++ 473: "Here's to my love! [Drinks.] O true apothecary! " ++ 474: "Thy drugs are quick. Thus with a kiss I die.".