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.".