lager_test_backend.erl 37.2 KB
Newer Older
Andrew Thompson's avatar
Andrew Thompson committed
1
%% Copyright (c) 2011-2012 Basho Technologies, Inc.  All Rights Reserved.
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
%%
%% This file is provided to you under the Apache License,
%% Version 2.0 (the "License"); you may not use this file
%% except in compliance with the License.  You may obtain
%% a copy of the License at
%%
%%   http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing,
%% software distributed under the License is distributed on an
%% "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
%% KIND, either express or implied.  See the License for the
%% specific language governing permissions and limitations
%% under the License.

-module(lager_test_backend).

19
20
-include("lager.hrl").

21
22
23
24
25
-behaviour(gen_event).

-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
        code_change/3]).

Andrew Thompson's avatar
Andrew Thompson committed
26
-record(state, {level, buffer, ignored}).
27
28
29
30
-compile([{parse_transform, lager_transform}]).

-ifdef(TEST).
-include_lib("eunit/include/eunit.hrl").
Andrew Thompson's avatar
Andrew Thompson committed
31
-export([pop/0, count/0, count_ignored/0, flush/0]).
32
33
-endif.

34
init(Level) ->
Andrew Thompson's avatar
Andrew Thompson committed
35
    {ok, #state{level=lager_util:level_to_num(Level), buffer=[], ignored=[]}}.
36
37
38

handle_call(count, #state{buffer=Buffer} = State) ->
    {ok, length(Buffer), State};
Andrew Thompson's avatar
Andrew Thompson committed
39
40
handle_call(count_ignored, #state{ignored=Ignored} = State) ->
    {ok, length(Ignored), State};
41
42
handle_call(flush, State) ->
    {ok, ok, State#state{buffer=[], ignored=[]}};
43
44
45
46
47
48
49
50
51
52
53
54
55
56
handle_call(pop, #state{buffer=Buffer} = State) ->
    case Buffer of
        [] ->
            {ok, undefined, State};
        [H|T] ->
            {ok, H, State#state{buffer=T}}
    end;
handle_call(get_loglevel, #state{level=Level} = State) ->
    {ok, Level, State};
handle_call({set_loglevel, Level}, State) ->
    {ok, ok, State#state{level=lager_util:level_to_num(Level)}};
handle_call(_Request, State) ->
    {ok, ok, State}.

57
58
handle_event(#lager_log_message{severity_as_int=Level,timestamp=Time, message=Message, metadata=Metadata}=Msg, 
        #state{level=LogLevel,buffer=Buffer,ignored=Ignored} = State) ->
59
        case lager_util:is_loggable(Msg, LogLevel, ?MODULE) of
60
61
62
            true ->   {ok, State#state{buffer=Buffer ++ [{Level, Time, Message, Metadata}]}};
            _ ->  {ok, State#state{ignored=Ignored ++ [ignored]}}
        end;
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
handle_event(_Event, State) ->
    {ok, State}.

handle_info(_Info, State) ->
    {ok, State}.

terminate(_Reason, _State) ->
    ok.

code_change(_OldVsn, State, _Extra) ->
    {ok, State}.

-ifdef(TEST).

pop() ->
Andrew Thompson's avatar
Andrew Thompson committed
78
    gen_event:call(lager_event, ?MODULE, pop).
79
80

count() ->
Andrew Thompson's avatar
Andrew Thompson committed
81
    gen_event:call(lager_event, ?MODULE, count).
82

Andrew Thompson's avatar
Andrew Thompson committed
83
count_ignored() ->
Andrew Thompson's avatar
Andrew Thompson committed
84
    gen_event:call(lager_event, ?MODULE, count_ignored).
Andrew Thompson's avatar
Andrew Thompson committed
85

Andrew Thompson's avatar
Andrew Thompson committed
86
87
88
flush() ->
    gen_event:call(lager_event, ?MODULE, flush).

89
has_line_numbers() ->
90
91
92
93
    %% are we R15 or greater
    Rel = erlang:system_info(otp_release),
    {match, [Major]} = re:run(Rel, "^R(\\d+)[A|B](|0(\\d))$", [{capture, [1], list}]),
    list_to_integer(Major) >= 15.
94

95
not_running_test() ->
96
    ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).
97

98
99
100
101
102
103
104
105
106
107
108
lager_test_() ->
    {foreach,
        fun setup/0,
        fun cleanup/1,
        [
            {"observe that there is nothing up my sleeve",
                fun() ->
                        ?assertEqual(undefined, pop()),
                        ?assertEqual(0, count())
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
109
            {"logging works",
110
111
112
                fun() ->
                        lager:warning("test message"),
                        ?assertEqual(1, count()),
113
                        {Level, _Time, Message, _Metadata}  = pop(),
114
                        ?assertMatch(Level, lager_util:level_to_num(warning)),
115
                        ?assertEqual("test message", Message),
116
117
118
                        ok
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
119
            {"logging with arguments works",
120
121
122
                fun() ->
                        lager:warning("test message ~p", [self()]),
                        ?assertEqual(1, count()),
123
                        {Level, _Time, Message,_Metadata}  = pop(),
124
                        ?assertMatch(Level, lager_util:level_to_num(warning)),
125
                        ?assertEqual(lists:flatten(io_lib:format("test message ~p", [self()])), lists:flatten(Message)),
126
127
128
                        ok
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
129
            {"logging works from inside a begin/end block",
130
131
132
133
134
135
136
137
138
                fun() ->
                        ?assertEqual(0, count()),
                        begin
                                lager:warning("test message 2")
                        end,
                        ?assertEqual(1, count()),
                        ok
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
139
            {"logging works from inside a list comprehension",
140
141
                fun() ->
                        ?assertEqual(0, count()),
142
                        [lager:warning("test message") || _N <- lists:seq(1, 10)],
143
144
145
146
                        ?assertEqual(10, count()),
                        ok
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
147
            {"logging works from a begin/end block inside a list comprehension",
148
149
                fun() ->
                        ?assertEqual(0, count()),
150
                        [ begin lager:warning("test message") end || _N <- lists:seq(1, 10)],
151
152
153
154
                        ?assertEqual(10, count()),
                        ok
                end
            },
Andrew Thompson's avatar
Andrew Thompson committed
155
            {"logging works from a nested list comprehension",
156
157
                fun() ->
                        ?assertEqual(0, count()),
158
159
                        [ [lager:warning("test message") || _N <- lists:seq(1, 10)] ||
                            _I <- lists:seq(1, 10)],
160
161
162
                        ?assertEqual(100, count()),
                        ok
                end
Andrew Thompson's avatar
Andrew Thompson committed
163
164
165
166
167
168
169
            },
            {"log messages below the threshold are ignored",
                fun() ->
                        ?assertEqual(0, count()),
                        lager:debug("this message will be ignored"),
                        ?assertEqual(0, count()),
                        ?assertEqual(0, count_ignored()),
170
                        lager_mochiglobal:put(loglevel, {?DEBUG, []}),
Andrew Thompson's avatar
Andrew Thompson committed
171
172
173
                        lager:debug("this message should be ignored"),
                        ?assertEqual(0, count()),
                        ?assertEqual(1, count_ignored()),
Andrew Thompson's avatar
Andrew Thompson committed
174
                        lager:set_loglevel(?MODULE, debug),
Andrew Thompson's avatar
Andrew Thompson committed
175
176
177
                        lager:debug("this message should be logged"),
                        ?assertEqual(1, count()),
                        ?assertEqual(1, count_ignored()),
Andrew Thompson's avatar
Andrew Thompson committed
178
                        ?assertEqual(debug, lager:get_loglevel(?MODULE)),
Andrew Thompson's avatar
Andrew Thompson committed
179
180
                        ok
                end
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
            },
            {"tracing works",
                fun() ->
                        lager_mochiglobal:put(loglevel, {?ERROR, []}),
                        ok = lager:info("hello world"),
                        ?assertEqual(0, count()),
                        lager_mochiglobal:put(loglevel, {?ERROR, [{[{module,
                                                ?MODULE}], ?DEBUG, ?MODULE}]}),
                        ok = lager:info("hello world"),
                        ?assertEqual(1, count()),
                        ok
                end
            },
            {"tracing works with custom attributes",
                fun() ->
                        lager_mochiglobal:put(loglevel, {?ERROR, []}),
                        lager:info([{requestid, 6}], "hello world"),
                        ?assertEqual(0, count()),
                        lager_mochiglobal:put(loglevel, {?ERROR,
                                [{[{requestid, 6}], ?DEBUG, ?MODULE}]}),
                        lager:info([{requestid, 6}, {foo, bar}], "hello world"),
                        ?assertEqual(1, count()),
                        lager_mochiglobal:put(loglevel, {?ERROR,
                                [{[{requestid, '*'}], ?DEBUG, ?MODULE}]}),
                        lager:info([{requestid, 6}], "hello world"),
                        ?assertEqual(2, count()),
                        ok
                end
            },
            {"tracing honors loglevel",
                fun() ->
                        lager_mochiglobal:put(loglevel, {?ERROR, [{[{module,
                                                ?MODULE}], ?NOTICE, ?MODULE}]}),
                        ok = lager:info("hello world"),
                        ?assertEqual(0, count()),
                        ok = lager:notice("hello world"),
                        ?assertEqual(1, count()),
                        ok
                end
220
221
222
223
224
            }
        ]
    }.

setup() ->
Andrew Thompson's avatar
Andrew Thompson committed
225
    error_logger:tty(false),
226
    application:load(lager),
227
    application:set_env(lager, handlers, [{?MODULE, info}]),
228
    application:set_env(lager, error_logger_redirect, false),
229
230
    application:start(compiler),
    application:start(syntax_tools),
231
232
    application:start(lager),
    gen_event:call(lager_event, ?MODULE, flush).
233
234
235

cleanup(_) ->
    application:stop(lager),
Andrew Thompson's avatar
Andrew Thompson committed
236
    error_logger:tty(true).
237

238
239
240

crash(Type) ->
    spawn(fun() -> gen_server:call(crash, Type) end),
241
242
    timer:sleep(100),
    _ = gen_event:which_handlers(error_logger),
243
244
    ok.

245
test_body(Expected, Actual) ->
246
247
248
249
250
    case has_line_numbers() of
        true ->
            FileLine = string:substr(Actual, length(Expected)+1),
            Body = string:substr(Actual, 1, length(Expected)),
            ?assertEqual(Expected, Body),
251
252
253
254
255
256
257
258
259
260
            case string:substr(FileLine, 1, 6) of
                [] ->
                    %% sometimes there's no line information...
                    ?assert(true);
                " line " ->
                    ?assert(true);
                Other ->
                    ?debugFmt("unexpected trailing data ~p", [Other]),
                    ?assert(false)
            end;
261
262
263
264
265
        false ->
            ?assertEqual(Expected, Actual)
    end.


266
error_logger_redirect_crash_test_() ->
267
268
269
270
271
272
273
274
275
276
277
    TestBody=fun(Name,CrashReason,Expected) -> {Name,
                fun() ->
                        Pid = whereis(crash),
                        crash(CrashReason),
                        {Level, _, Msg,Metadata} = pop(),
                        test_body(Expected, lists:flatten(Msg)),
                        ?assertEqual(Pid,proplists:get_value(pid,Metadata)),
                        ?assertEqual(lager_util:level_to_num(error),Level)
                end
            } 
    end,
278
279
    {foreach,
        fun() ->
Andrew Thompson's avatar
Andrew Thompson committed
280
                error_logger:tty(false),
281
282
                application:load(lager),
                application:set_env(lager, error_logger_redirect, true),
283
                application:set_env(lager, handlers, [{?MODULE, error}]),
284
285
                application:start(compiler),
                application:start(syntax_tools),
286
287
288
289
290
291
292
293
294
                application:start(lager),
                crash:start()
        end,

        fun(_) ->
                application:stop(lager),
                case whereis(crash) of
                    undefined -> ok;
                    Pid -> exit(Pid, kill)
Andrew Thompson's avatar
Andrew Thompson committed
295
296
                end,
                error_logger:tty(true)
297
298
299
300
301
302
303
304
        end,
        [
            {"again, there is nothing up my sleeve",
                fun() ->
                        ?assertEqual(undefined, pop()),
                        ?assertEqual(0, count())
                end
            },
305

306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
            TestBody("bad return value",bad_return,"gen_server crash terminated with reason: bad return value: bleh"),
            TestBody("bad return value with string",bad_return_string,"gen_server crash terminated with reason: bad return value: {tuple,{tuple,\"string\"}}"),
            TestBody("bad return uncaught throw",throw,"gen_server crash terminated with reason: bad return value: a_ball"),
            TestBody("case clause",case_clause,"gen_server crash terminated with reason: no case clause matching {} in crash:handle_call/3"),
            TestBody("case clause string",case_clause_string,"gen_server crash terminated with reason: no case clause matching \"crash\" in crash:handle_call/3"),
            TestBody("function clause",function_clause,"gen_server crash terminated with reason: no function clause matching crash:function({})"),
            TestBody("if clause",if_clause,"gen_server crash terminated with reason: no true branch found while evaluating if expression in crash:handle_call/3"),
            TestBody("try clause",try_clause,"gen_server crash terminated with reason: no try clause matching [] in crash:handle_call/3"),
            TestBody("undefined function",undef,"gen_server crash terminated with reason: call to undefined function crash:booger/0 from crash:handle_call/3"),
            TestBody("bad math",badarith,"gen_server crash terminated with reason: bad arithmetic expression in crash:handle_call/3"),
            TestBody("bad match",badmatch,"gen_server crash terminated with reason: no match of right hand value {} in crash:handle_call/3"),
            TestBody("bad arity",badarity,"gen_server crash terminated with reason: fun called with wrong arity of 1 instead of 3 in crash:handle_call/3"),
            TestBody("bad arg1",badarg1,"gen_server crash terminated with reason: bad argument in crash:handle_call/3"),
            TestBody("bad arg2",badarg2,"gen_server crash terminated with reason: bad argument in call to erlang:iolist_to_binary([\"foo\",bar]) in crash:handle_call/3"),
            TestBody("bad record",badrecord,"gen_server crash terminated with reason: bad record state in crash:handle_call/3"),
            TestBody("noproc",noproc,"gen_server crash terminated with reason: no such process or port in call to gen_event:call(foo, bar, baz)"),
            TestBody("badfun",badfun,"gen_server crash terminated with reason: bad function booger in crash:handle_call/3")
323
324
325
        ]
    }.

326
327
328
error_logger_redirect_test_() ->
    {foreach,
        fun() ->
Andrew Thompson's avatar
Andrew Thompson committed
329
                error_logger:tty(false),
330
331
                application:load(lager),
                application:set_env(lager, error_logger_redirect, true),
332
                application:set_env(lager, handlers, [{?MODULE, info}]),
333
                application:start(lager),
334
                lager:log(error, self(), "flush flush"),
335
336
337
338
339
340
                timer:sleep(100),
                gen_event:call(lager_event, ?MODULE, flush)
        end,

        fun(_) ->
                application:stop(lager),
Andrew Thompson's avatar
Andrew Thompson committed
341
                error_logger:tty(true)
342
343
344
345
        end,
        [
            {"error reports are printed",
                fun() ->
346
347
                        sync_error_logger:error_report([{this, is}, a, {silly, format}]),
                        _ = gen_event:which_handlers(error_logger),
348
349
350
351
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = "this: is, a, silly: format",
352
                        ?assertEqual(Expected, lists:flatten(Msg))
353

354
355
356
357
                end
            },
            {"string error reports are printed",
                fun() ->
358
359
                        sync_error_logger:error_report("this is less silly"),
                        _ = gen_event:which_handlers(error_logger),
360
361
362
363
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = "this is less silly",
364
365
366
367
368
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"error messages are printed",
                fun() ->
369
370
                        sync_error_logger:error_msg("doom, doom has come upon you all"),
                        _ = gen_event:which_handlers(error_logger),
371
372
373
374
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = "doom, doom has come upon you all",
375
376
377
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
378
379
            {"error messages are truncated at 4096 characters",
                fun() ->
380
381
                        sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
                        _ = gen_event:which_handlers(error_logger),
382
                        {_, _, Msg,_Metadata} = pop(),
383
384
385
                        ?assert(length(lists:flatten(Msg)) < 5100)
                end
            },
386
387
            {"info reports are printed",
                fun() ->
388
389
                        sync_error_logger:info_report([{this, is}, a, {silly, format}]),
                        _ = gen_event:which_handlers(error_logger),
390
391
392
393
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = "this: is, a, silly: format",
394
395
396
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
397
398
            {"info reports are truncated at 4096 characters",
                fun() ->
399
400
                        sync_error_logger:info_report([[{this, is}, a, {silly, format}] || _ <- lists:seq(0, 600)]),
                        _ = gen_event:which_handlers(error_logger),
401
402
403
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
404
405
406
                        ?assert(length(lists:flatten(Msg)) < 5000)
                end
            },
407
408
            {"single term info reports are printed",
                fun() ->
409
410
                        sync_error_logger:info_report({foolish, bees}),
                        _ = gen_event:which_handlers(error_logger),
411
412
413
414
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("{foolish,bees}", lists:flatten(Msg))
415
416
417
418
                end
            },
            {"single term error reports are printed",
                fun() ->
419
420
                        sync_error_logger:error_report({foolish, bees}),
                        _ = gen_event:which_handlers(error_logger),
421
422
423
424
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("{foolish,bees}", lists:flatten(Msg))
425
426
                end
            },
427
428
            {"string info reports are printed",
                fun() ->
429
430
                        sync_error_logger:info_report("this is less silly"),
                        _ = gen_event:which_handlers(error_logger),
431
432
433
434
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("this is less silly", lists:flatten(Msg))
435
436
                end
            },
437
438
            {"string info reports are truncated at 4096 characters",
                fun() ->
439
440
                        sync_error_logger:info_report(string:copies("this is less silly", 1000)),
                        _ = gen_event:which_handlers(error_logger),
441
442
443
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
444
445
446
                        ?assert(length(lists:flatten(Msg)) < 5100)
                end
            },
447
448
449
450
            {"strings in a mixed report are printed as strings",
                fun() ->
                        sync_error_logger:info_report(["this is less silly", {than, "this"}]),
                        _ = gen_event:which_handlers(error_logger),
451
452
453
454
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("\"this is less silly\", than: \"this\"", lists:flatten(Msg))
455
456
                end
            },
457
            {"info messages are printed",
458
                fun() ->
459
460
                        sync_error_logger:info_msg("doom, doom has come upon you all"),
                        _ = gen_event:which_handlers(error_logger),
461
462
463
464
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg))
465
466
                end
            },
467
468
            {"info messages are truncated at 4096 characters",
                fun() ->
469
470
                        sync_error_logger:info_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
                        _ = gen_event:which_handlers(error_logger),
471
472
473
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
474
475
476
477
                        ?assert(length(lists:flatten(Msg)) < 5100)
                end
            },

478
479
            {"warning messages are printed at the correct level",
                fun() ->
480
                        sync_error_logger:warning_msg("doom, doom has come upon you all"),
481
                        Map = error_logger:warning_map(),
482
                        _ = gen_event:which_handlers(error_logger),
483
484
485
486
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(Map),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg))
487
488
489
490
                end
            },
            {"warning reports are printed at the correct level",
                fun() ->
491
                        sync_error_logger:warning_report([{i, like}, pie]),
492
                        Map = error_logger:warning_map(),
493
                        _ = gen_event:which_handlers(error_logger),
494
495
496
497
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(Map),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("i: like, pie", lists:flatten(Msg))
498
499
                end
            },
500
501
            {"single term warning reports are printed at the correct level",
                fun() ->
502
                        sync_error_logger:warning_report({foolish, bees}),
503
                        Map = error_logger:warning_map(),
504
                        _ = gen_event:which_handlers(error_logger),
505
506
507
508
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(Map),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("{foolish,bees}", lists:flatten(Msg))
509
510
                end
            },
511
512
            {"application stop reports",
                fun() ->
513
514
                        sync_error_logger:info_report([{application, foo}, {exited, quittin_time}, {type, lazy}]),
                        _ = gen_event:which_handlers(error_logger),
515
516
517
518
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("Application foo exited with reason: quittin_time", lists:flatten(Msg))
519
520
521
522
                end
            },
            {"supervisor reports",
                fun() ->
523
524
                        sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
                        _ = gen_event:which_handlers(error_logger),
525
526
527
528
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason fired in context france", lists:flatten(Msg))
529
530
                end
            },
531
532
            {"supervisor reports with real error",
                fun() ->
533
534
                        sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{name, mini_steve}, {mfargs, {a, b, [c]}}, {pid, bleh}]}, {reason, {function_clause,[{crash,handle_info,[foo]}]}}, {supervisor, {local, steve}}]),
                        _ = gen_event:which_handlers(error_logger),
535
536
537
538
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("Supervisor steve had child mini_steve started with a:b(c) at bleh exit with reason no function clause matching crash:handle_info(foo) in context france", lists:flatten(Msg))
539
540
541
                end
            },

542
543
            {"supervisor_bridge reports",
                fun() ->
544
545
                        sync_error_logger:error_report(supervisor_report, [{errorContext, france}, {offender, [{mod, mini_steve}, {pid, bleh}]}, {reason, fired}, {supervisor, {local, steve}}]),
                        _ = gen_event:which_handlers(error_logger),
546
547
548
549
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("Supervisor steve had child at module mini_steve at bleh exit with reason fired in context france", lists:flatten(Msg))
550
                end
551
552
553
            },
            {"application progress report",
                fun() ->
554
555
                        sync_error_logger:info_report(progress, [{application, foo}, {started_at, node()}]),
                        _ = gen_event:which_handlers(error_logger),
556
557
558
559
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(info),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("Application foo started on node ~w", [node()])),
560
561
562
563
564
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"supervisor progress report",
                fun() ->
Andrew Thompson's avatar
Andrew Thompson committed
565
                        lager:set_loglevel(?MODULE, debug),
566
567
                        sync_error_logger:info_report(progress, [{supervisor, {local, foo}}, {started, [{mfargs, {foo, bar, 1}}, {pid, baz}]}]),
                        _ = gen_event:which_handlers(error_logger),
568
569
570
571
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(debug),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        ?assertEqual("Supervisor foo started foo:bar/1 at pid baz", lists:flatten(Msg))
572
                end
573
            },
574
575
            {"crash report for emfile",
                fun() ->
576
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, emfile, [{stack, trace, 1}]}}], []]),
577
                        _ = gen_event:which_handlers(error_logger),
578
579
580
581
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: maximum number of file descriptors exhausted, check ulimit -n", [self()])),
582
583
584
585
586
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"crash report for system process limit",
                fun() ->
587
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn, 1}]}}], []]),
588
                        _ = gen_event:which_handlers(error_logger),
589
590
591
592
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])),
593
594
595
596
597
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"crash report for system process limit2",
                fun() ->
598
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, spawn_opt, 1}]}}], []]),
599
                        _ = gen_event:which_handlers(error_logger),
600
601
602
603
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of processes exceeded", [self()])),
604
605
606
607
608
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"crash report for system port limit",
                fun() ->
609
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, open_port, 1}]}}], []]),
610
                        _ = gen_event:which_handlers(error_logger),
611
612
613
614
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ports exceeded", [self()])),
615
616
617
618
619
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
            {"crash report for system port limit",
                fun() ->
620
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, []}, {error_info, {error, system_limit, [{erlang, list_to_atom, 1}]}}], []]),
621
                        _ = gen_event:which_handlers(error_logger),
622
623
624
625
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: tried to create an atom larger than 255, or maximum atom count exceeded", [self()])),
626
627
628
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
629
630
            {"crash report for system ets table limit",
                fun() ->
631
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {registered_name, test}, {error_info, {error, system_limit, [{ets,new,[segment_offsets,[ordered_set,public]]},{mi_segment,open_write,1},{mi_buffer_converter,handle_cast,2},{gen_server,handle_msg,5},{proc_lib,init_p_do_apply,3}]}}], []]),
632
                        _ = gen_event:which_handlers(error_logger),
633
634
635
636
                        {Level, _, Msg,Metadata} = pop(),
                        ?assertEqual(lager_util:level_to_num(error),Level),
                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~w with 0 neighbours crashed with reason: system limit: maximum number of ETS tables exceeded", [test])),
637
638
639
                        ?assertEqual(Expected, lists:flatten(Msg))
                end
            },
640
641
            {"crash report for unknown system limit should be truncated at 500 characters",
                fun() ->
642
                        sync_error_logger:error_report(crash_report, [[{pid, self()}, {error_info, {error, system_limit, [{wtf,boom,[string:copies("aaaa", 4096)]}]}}], []]),
643
                        _ = gen_event:which_handlers(error_logger),
644
645
646
                        {_, _, Msg,_Metadata} = pop(),
                        ?assert(length(lists:flatten(Msg)) > 550),
                        ?assert(length(lists:flatten(Msg)) < 600)
647
648
                end
            },
649
            {"crash reports for 'special processes' should be handled right - function_clause", 
650
651
652
653
654
655
                fun() ->
                        {ok, Pid} = special_process:start(),
                        unlink(Pid),
                        Pid ! function_clause,
                        timer:sleep(500),
                        _ = gen_event:which_handlers(error_logger),
656
657
658
                        {_, _, Msg, _Metadata} = pop(),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no function clause matching special_process:foo(bar)",
                                [Pid])),
659
                        test_body(Expected, lists:flatten(Msg))
660
661
                end
            },
662
663
664
665
666
667
668
            {"crash reports for 'special processes' should be handled right - case_clause", 
                fun() ->
                        {ok, Pid} = special_process:start(),
                        unlink(Pid),
                        Pid ! {case_clause, wtf},
                        timer:sleep(500),
                        _ = gen_event:which_handlers(error_logger),
669
670
671
                        {_, _, Msg, _Metadata} = pop(),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: no case clause matching wtf in special_process:loop/0",
                                [Pid])),
672
673
674
675
676
677
678
679
680
681
                        test_body(Expected, lists:flatten(Msg))
                end
            },
            {"crash reports for 'special processes' should be handled right - exit", 
                fun() ->
                        {ok, Pid} = special_process:start(),
                        unlink(Pid),
                        Pid ! exit,
                        timer:sleep(500),
                        _ = gen_event:which_handlers(error_logger),
682
683
684
                        {_, _, Msg, _Metadata} = pop(),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours exited with reason: byebye in special_process:loop/0",
                                [Pid])),
685
686
687
688
689
690
691
692
693
694
                        test_body(Expected, lists:flatten(Msg))
                end
            },
            {"crash reports for 'special processes' should be handled right - error", 
                fun() ->
                        {ok, Pid} = special_process:start(),
                        unlink(Pid),
                        Pid ! error,
                        timer:sleep(500),
                        _ = gen_event:which_handlers(error_logger),
695
696
697
                        {_, _, Msg, _Metadata} = pop(),
                        Expected = lists:flatten(io_lib:format("CRASH REPORT Process ~p with 0 neighbours crashed with reason: mybad in special_process:loop/0",
                                [Pid])),
698
699
700
                        test_body(Expected, lists:flatten(Msg))
                end
            },
701
702
703
            {"messages should not be generated if they don't satisfy the threshold",
                fun() ->
                        lager:set_loglevel(?MODULE, error),
704
705
                        sync_error_logger:info_report([hello, world]),
                        _ = gen_event:which_handlers(error_logger),
706
707
708
                        ?assertEqual(0, count()),
                        ?assertEqual(0, count_ignored()),
                        lager:set_loglevel(?MODULE, info),
709
710
                        sync_error_logger:info_report([hello, world]),
                        _ = gen_event:which_handlers(error_logger),
711
712
713
                        ?assertEqual(1, count()),
                        ?assertEqual(0, count_ignored()),
                        lager:set_loglevel(?MODULE, error),
714
                        lager_mochiglobal:put(loglevel, {?DEBUG, []}),
715
716
                        sync_error_logger:info_report([hello, world]),
                        _ = gen_event:which_handlers(error_logger),
717
718
719
                        ?assertEqual(1, count()),
                        ?assertEqual(1, count_ignored())
                end
720
721
722
723
            }
        ]
    }.

724
725
726
727
728
safe_format_test() ->
    ?assertEqual("foo bar", lists:flatten(lager:safe_format("~p ~p", [foo, bar], 1024))),
    ?assertEqual("FORMAT ERROR: \"~p ~p ~p\" [foo,bar]", lists:flatten(lager:safe_format("~p ~p ~p", [foo, bar], 1024))),
    ok.

729
730
731
-endif.