README.md 20.6 KB
Newer Older
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Overview
--------
Lager (as in the beer) is a logging framework for Erlang. Its purpose is
to provide a more traditional way to perform logging in an erlang application
that plays nicely with traditional UNIX logging tools like logrotate and
syslog.

  [Travis-CI](http://travis-ci.org/basho/lager) :: ![Travis-CI](https://secure.travis-ci.org/basho/lager.png)

Features
--------
* Finer grained log levels (debug, info, notice, warning, error, critical,
  alert, emergency)
* Logger calls are transformed using a parse transform to allow capturing
  Module/Function/Line/Pid information
16
* When no handler is consuming a log level (eg. debug) no event is sent
17
18
  to the log handler
* Supports multiple backends, including console and file.
19
* Supports multiple sinks
20
21
22
* Rewrites common OTP error messages into more readable messages
* Support for pretty printing records encountered at compile time
* Tolerant in the face of large or many log messages, won't out of memory the node
23
* Optional feature to bypass log size truncation ("unsafe")
24
25
26
* Supports internal time and date based rotation, as well as external rotation tools
* Syslog style log level comparison flags
* Colored terminal output (requires R16+)
27
* Map support (requires 17+)
28
29
30
31

Usage
-----
To use lager in your application, you need to define it as a rebar dep or have
32
33
some other way of including it in Erlang's path. You can then add the
following option to the erlang compiler flags:
34
35
36
37
38
39
40
41
42
43
44
45
46

```erlang
{parse_transform, lager_transform}
```

Alternately, you can add it to the module you wish to compile with logging
enabled:

```erlang
-compile([{parse_transform, lager_transform}]).
```

Before logging any messages, you'll need to start the lager application. The
47
lager module's `start` function takes care of loading and starting any dependencies
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
lager requires.

```erlang
lager:start().
```

You can also start lager on startup with a switch to `erl`:

```erlang
erl -pa path/to/lager/ebin -s lager
```

Once you have built your code with lager and started the lager application,
you can then generate log messages by doing the following:

```erlang
lager:error("Some message")
```

  Or:

```erlang
lager:warning("Some message with a term: ~p", [Term])
```

73
The general form is `lager:Severity()` where `Severity` is one of the log levels
74
75
76
77
78
79
80
81
82
mentioned above.

Configuration
-------------
To configure lager's backends, you use an application variable (probably in
your app.config):

```erlang
{lager, [
83
  {log_root, "/var/log/hello"},
84
85
86
87
88
89
90
91
  {handlers, [
    {lager_console_backend, info},
    {lager_file_backend, [{file, "error.log"}, {level, error}]},
    {lager_file_backend, [{file, "console.log"}, {level, info}]}
  ]}
]}.
```

92
93
```log_root``` variable is optional, by default file paths are relative to CWD.

94
95
96
The available configuration options for each backend are listed in their
module's documentation.

97
98
99
100
101
102
103
104
105
106
Sinks
-----
Lager has traditionally supported a single sink (implemented as a
`gen_event` manager) named `lager_event` to which all backends were
connected.

Lager now supports extra sinks; each sink can have different
sync/async message thresholds and different backends.

### Sink configuration
Mark Allen's avatar
Mark Allen committed
107

108
To use multiple sinks (beyond the built-in sink of lager and lager_event), you
Mark Allen's avatar
Mark Allen committed
109
110
111
112
113
need to:

1. Setup rebar.config
2. Configure the backends in app.config

114
115
116
#### Names

Each sink has two names: one atom to be used like a module name for
Mark Allen's avatar
Mark Allen committed
117
sending messages, and that atom with `_lager_event` appended for backend
118
119
120
121
122
configuration.

This reflects the legacy behavior: `lager:info` (or `critical`, or
`debug`, etc) is a way of sending a message to a sink named
`lager_event`. Now developers can invoke `audit:info` or
Mark Allen's avatar
Mark Allen committed
123
124
`myCompanyName:debug` so long as the corresponding `audit_lager_event` or
`myCompanyName_lager_event` sinks are configured.
125
126

#### rebar.config
Mark Allen's avatar
Mark Allen committed
127

128
In `rebar.config` for the project that requires lager, include a list
Mark Allen's avatar
Mark Allen committed
129
of sink names (without the `_lager_event` suffix) in `erl_opts`:
Mark Allen's avatar
Mark Allen committed
130

131
`{lager_extra_sinks, [audit]}`
Mark Allen's avatar
Mark Allen committed
132

133
#### Runtime requirements
Mark Allen's avatar
Mark Allen committed
134

135
To be useful, sinks must be configured at runtime with backends.
Mark Allen's avatar
Mark Allen committed
136

137
138
139
140
141
142
In `app.config` for the project that requires lager, for example,
extend the lager configuration to include an `extra_sinks` tuple with
backends (aka "handlers") and optionally `async_threshold` and
`async_threshold_window` values (see **Overload Protection**
below). If async values are not configured, no overload protection
will be applied on that sink.
Mark Allen's avatar
Mark Allen committed
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157

```erlang
[{lager, [
          {log_root, "/tmp"},

          %% Default handlers for lager/lager_event
          {handlers, [
                      {lager_console_backend, info},
                      {lager_file_backend, [{file, "error.log"}, {level, error}]},
                      {lager_file_backend, [{file, "console.log"}, {level, info}]}
                     ]},

          %% Any other sinks
          {extra_sinks,
           [
Mark Allen's avatar
Mark Allen committed
158
            {audit_lager_event,
Mark Allen's avatar
Mark Allen committed
159
160
161
162
163
164
             [{handlers,
               [{lager_file_backend,
                 [{file, "sink1.log"},
                  {level, info}
                 ]
                }]
165
166
167
              },
              {async_threshold, 500},
              {async_threshold_window, 50}]
Mark Allen's avatar
Mark Allen committed
168
169
170
171
172
173
174
            }]
          }
         ]
 }
].
```

175
176
177
Custom Formatting
-----------------
All loggers have a default formatting that can be overriden.  A formatter is any module that
178
exports `format(#lager_log_message{},Config#any())`.  It is specified as part of the configuration
179
180
181
182
183
for the backend:

```erlang
{lager, [
  {handlers, [
184
185
    {lager_console_backend, [info, {lager_default_formatter, [time," [",severity,"] ", message, "\n"]}]},
    {lager_file_backend, [{file, "error.log"}, {level, error}, {formatter, lager_default_formatter},
186
      {formatter_config, [date, " ", time," [",severity,"] ",pid, " ", message, "\n"]}]},
187
    {lager_file_backend, [{file, "console.log"}, {level, info}]}
188
189
190
191
  ]}
]}.
```

192
193
194
195
Included is `lager_default_formatter`.  This provides a generic, default formatting for log messages using a structure similar to Erlang's [iolist](http://learnyousomeerlang.com/buckets-of-sockets#io-lists) which we call "semi-iolist":

* Any traditional iolist elements in the configuration are printed verbatim.
* Atoms in the configuration are treated as placeholders for lager metadata and extracted from the log message.
196
197
198
    * The placeholders `date`, `time`, `message`, `sev` and `severity` will always exist.
    * `sev` is an abbreviated severity which is interpreted as a capitalized single letter encoding of the severity level
      (e.g. `'debug'` -> `$D`)
199
200
201
202
203
204
205
206
207
208
209
    * The placeholders `pid`, `file`, `line`, `module`, `function`, and `node` will always exist if the parse transform is used.
    * Applications can define their own metadata placeholder.
    * A tuple of `{atom(), semi-iolist()}` allows for a fallback for
      the atom placeholder. If the value represented by the atom
      cannot be found, the semi-iolist will be interpreted instead.
    * A tuple of `{atom(), semi-iolist(), semi-iolist()}` represents a
      conditional operator: if a value for the atom placeholder can be
      found, the first semi-iolist will be output; otherwise, the
      second will be used.

Examples:
210
211
212
213
214

```
["Foo"] -> "Foo", regardless of message content.
[message] -> The content of the logged message, alone.
[{pid,"Unknown Pid"}] -> "<?.?.?>" if pid is in the metadata, "Unknown Pid" if not.
215
216
[{pid, ["My pid is ", pid], ["Unknown Pid"]}] -> if pid is in the metadata print "My pid is <?.?.?>", otherwise print "Unknown Pid"
[{server,{pid, ["(", pid, ")"], ["(Unknown Server)"]}}] -> user provided server metadata, otherwise "(<?.?.?>)", otherwise "(Unknown Server)"
217
218
219
220
```

Error logger integration
------------------------
221
Lager is also supplied with a `error_logger` handler module that translates
222
223
traditional erlang error messages into a friendlier format and sends them into
lager itself to be treated like a regular lager log call. To disable this, set
Benedikt Sauer's avatar
Benedikt Sauer committed
224
the lager application variable `error_logger_redirect` to `false`.
Daniil Fedotov's avatar
typo    
Daniil Fedotov committed
225
You can also disable reformatting for OTP and Cowboy messages by setting variable
226
`error_logger_format_raw` to `true`.
227

228
229
The `error_logger` handler will also log more complete error messages (protected
with use of `trunc_io`) to a "crash log" which can be referred to for further
230
information. The location of the crash log can be specified by the crash_log
231
application variable. If set to `undefined` it is not written at all.
232
233

Messages in the crash log are subject to a maximum message size which can be
234
specified via the `crash_log_msg_size` application variable.
235

236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
Messages from `error_logger` will be redirected to `error_logger_lager_event` sink
if it is defined so it can be redirected to another log file.
For example:

```
[{lager, [
         {extra_sinks,
          [
           {error_logger_lager_event, 
            [{handlers, [
              {lager_file_backend, [{file, "error_logger.log"}, {level, info}]}]
              }]
           }]
           }]
}].
```
Will send all `error_logger` messages to `error_logger.log` file.
253
254
255
Overload Protection
-------------------

256
Prior to lager 2.0, the `gen_event` at the core of lager operated purely in
257
synchronous mode. Asynchronous mode is faster, but has no protection against
258
message queue overload. In lager 2.0, the `gen_event` takes a hybrid approach. it
259
260
261
262
polls its own mailbox size and toggles the messaging between synchronous and
asynchronous depending on mailbox size.

```erlang
263
264
{async_threshold, 20},
{async_threshold_window, 5}
265
266
267
```

This will use async messaging until the mailbox exceeds 20 messages, at which
268
269
point synchronous messaging will be used, and switch back to asynchronous, when
size reduces to `20 - 5 = 15`.
270

271
If you wish to disable this behaviour, simply set it to `undefined`. It defaults
272
273
274
275
to a low number to prevent the mailbox growing rapidly beyond the limit and causing
problems. In general, lager should process messages as fast as they come in, so getting
20 behind should be relatively exceptional anyway.

276
If you want to limit the number of messages per second allowed from `error_logger`,
277
278
279
280
281
282
283
284
285
which is a good idea if you want to weather a flood of messages when lots of
related processes crash, you can set a limit:

```erlang
{error_logger_hwm, 50}
```

It is probably best to keep this number small.

286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
"Unsafe"
--------
The unsafe code pathway bypasses the normal lager formatting code and uses the
same code as error_logger in OTP. This provides a marginal speedup to your logging
code (we measured between 0.5-1.3% improvement during our benchmarking; others have
reported better improvements.)

This is a **dangerous** feature. It *will not* protect you against
large log messages - large messages can kill your application and even your
Erlang VM dead due to memory exhaustion as large terms are copied over and
over in a failure cascade.  We strongly recommend that this code pathway
only be used by log messages with a well bounded upper size of around 500 bytes.

If there's any possibility the log messages could exceed that limit, you should
use the normal lager message formatting code which will provide the appropriate
size limitations and protection against memory exhaustion.

If you want to format an unsafe log message, you may use the severity level (as
usual) followed by `_unsafe`. Here's an example:

```erlang
lager:info_unsafe("The quick brown ~s jumped over the lazy ~s", ["fox", "dog"]).
```

310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
Runtime loglevel changes
------------------------
You can change the log level of any lager backend at runtime by doing the
following:

```erlang
lager:set_loglevel(lager_console_backend, debug).
```

  Or, for the backend with multiple handles (files, mainly):

```erlang
lager:set_loglevel(lager_file_backend, "console.log", debug).
```

325
326
Lager keeps track of the minimum log level being used by any backend and
suppresses generation of messages lower than that level. This means that debug
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
log messages, when no backend is consuming debug messages, are effectively
free. A simple benchmark of doing 1 million debug log messages while the
minimum threshold was above that takes less than half a second.

Syslog style loglevel comparison flags
--------------------------------------
In addition to the regular log level names, you can also do finer grained masking
of what you want to log:

```
info - info and higher (>= is implicit)
=debug - only the debug level
!=info - everything but the info level
<=notice - notice and below
<warning - anything less than warning
```

These can be used anywhere a loglevel is supplied, although they need to be either
a quoted atom or a string.

Internal log rotation
---------------------
Lager can rotate its own logs or have it done via an external process. To
350
use internal rotation, use the `size`, `date` and `count` values in the file
351
352
353
backend's config:

```erlang
354
[{file, "error.log"}, {level, error}, {size, 10485760}, {date, "$D0"}, {count, 5}]
355
356
```

357
358
359
This tells lager to log error and above messages to `error.log` and to
rotate the file at midnight or when it reaches 10mb, whichever comes first,
and to keep 5 rotated logs in addition to the current one. Setting the
360
361
362
363
count to 0 does not disable rotation, it instead rotates the file and keeps
no previous versions around. To disable rotation set the size to 0 and the
date to "".

364
The `$D0` syntax is taken from the syntax newsyslog uses in newsyslog.conf.
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
The relevant extract follows:

```
Day, week and month time format: The lead-in character
for day, week and month specification is a `$'-sign.
The particular format of day, week and month
specification is: [Dhh], [Ww[Dhh]] and [Mdd[Dhh]],
respectively.  Optional time fields default to
midnight.  The ranges for day and hour specifications
are:

  hh      hours, range 0 ... 23
  w       day of week, range 0 ... 6, 0 = Sunday
  dd      day of month, range 1 ... 31, or the
          letter L or l to specify the last day of
          the month.

Some examples:
  $D0     rotate every night at midnight
  $D23    rotate every day at 23:00 hr
  $W0D23  rotate every week on Sunday at 23:00 hr
  $W5D16  rotate every week on Friday at 16:00 hr
  $M1D0   rotate on the first day of every month at
          midnight (i.e., the start of the day)
  $M5D6   rotate on every 5th day of the month at
          6:00 hr
```

To configure the crash log rotation, the following application variables are
used:
395
396
397
* `crash_log_size`
* `crash_log_date`
* `crash_log_count`
398

399
See the `.app.src` file for further details.
400
401
402

Syslog Support
--------------
403
Lager syslog output is provided as a separate application:
404
[lager_syslog](https://github.com/basho/lager_syslog). It is packaged as a
405
406
separate application so lager itself doesn't have an indirect dependency on a
port driver. Please see the `lager_syslog` README for configuration information.
407
408
409
410
411
412
413

Older Backends
--------------
Lager 2.0 changed the backend API, there are various 3rd party backends for
lager available, but they may not have been updated to the new API. As they
are updated, links to them can be re-added here.

414
415
416
417
418
419
420
Exception Pretty Printing
----------------------

```erlang
try
    foo()
catch
421
422
423
424
    Class:Reason ->
        lager:error(
            "~nStacktrace:~s",
            [lager:pr_stacktrace(erlang:get_stacktrace(), {Class, Reason})])
425
426
427
end.
```

428
429
430
431
432
Record Pretty Printing
----------------------
Lager's parse transform will keep track of any record definitions it encounters
and store them in the module's attributes. You can then, at runtime, print any
record a module compiled with the lager parse transform knows about by using the
433
`lager:pr/2` function, which takes the record and the module that knows about the record:
434
435
436
437
438

```erlang
lager:info("My state is ~p", [lager:pr(State, ?MODULE)])
```

439
440
Often, `?MODULE` is sufficent, but you can obviously substitute that for a literal module name.
`lager:pr` also works from the shell.
441
442
443

Colored terminal output
-----------------------
444
445
If you have Erlang R16 or higher, you can tell lager's console backend to be colored. Simply
add to lager's application environment config:
446
447
448
449
450

```erlang
{colored, true}
```

451
452
If you don't like the default colors, they are also configurable; see
the `.app.src` file for more details.
453

454
455
456
457
458
459
460
461
462
463
464
The output will be colored from the first occurrence of the atom color
in the formatting configuration. For example:

```erlang
{lager_console_backend, [info, {lager_default_formatter, [time, color, " [",severity,"] ", message, "\e[0m\r\n"]}]}
```

This will make the entire log message, except time, colored. The
escape sequence before the line break is needed in order to reset the
color after each log message.

465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
Tracing
-------
Lager supports basic support for redirecting log messages based on log message
attributes. Lager automatically captures the pid, module, function and line at the
log message callsite. However, you can add any additional attributes you wish:

```erlang
lager:warning([{request, RequestID},{vhost, Vhost}], "Permission denied to ~s", [User])
```

Then, in addition to the default trace attributes, you'll be able to trace
based on request or vhost:

```erlang
lager:trace_file("logs/example.com.error", [{vhost, "example.com"}], error)
```

482
To persist metadata for the life of a process, you can use `lager:md/1` to store metadata
483
484
485
486
487
488
in the process dictionary:

```erlang
lager:md([{zone, forbidden}])
```

489
Note that `lager:md` will *only* accept a list of key/value pairs keyed by atoms.
490
491

You can also omit the final argument, and the loglevel will default to
492
`debug`.
493
494
495
496
497
498
499
500
501
502

Tracing to the console is similar:

```erlang
lager:trace_console([{request, 117}])
```

In the above example, the loglevel is omitted, but it can be specified as the
second argument if desired.

503
You can also specify multiple expressions in a filter, or use the `*` atom as
504
505
506
a wildcard to match any message that has that attribute, regardless of its
value.

John R. Daily's avatar
John R. Daily committed
507
508
Tracing to an existing logfile is also supported (but see **Multiple
sink support** below):
509
510

```erlang
511
lager:trace_file("log/error.log", [{module, mymodule}, {function, myfunction}], warning)
512
513
```

514
515
To view the active log backends and traces, you can use the `lager:status()`
function. To clear all active traces, you can use `lager:clear_all_traces()`.
516
517

To delete a specific trace, store a handle for the trace when you create it,
518
that you later pass to `lager:stop_trace/1`:
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536

```erlang
{ok, Trace} = lager:trace_file("log/error.log", [{module, mymodule}]),
...
lager:stop_trace(Trace)
```

Tracing to a pid is somewhat of a special case, since a pid is not a
data-type that serializes well. To trace by pid, use the pid as a string:

```erlang
lager:trace_console([{pid, "<0.410.0>"}])
```

As of lager 2.0, you can also use a 3 tuple while tracing, where the second
element is a comparison operator. The currently supported comparison operators
are:

537
538
539
* `<` - less than
* `=` - equal to
* `>` - greater than
540
541

```erlang
egobrain's avatar
egobrain committed
542
lager:trace_console([{request, '>', 117}, {request, '<', 120}])
543
544
```

545
Using `=` is equivalent to the 2-tuple form.
546

John R. Daily's avatar
John R. Daily committed
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
### Multiple sink support

If using multiple sinks, there are limitations on tracing that you
should be aware of.

Traces are specific to a sink, which can be specified via trace
filters:

```erlang
lager:trace_file("log/security.log", [{sink, audit}, {function, myfunction}], warning)
```

If no sink is thus specified, the default lager sink will be used.

This has two ramifications:

* Traces cannot intercept messages sent to a different sink.
* Tracing to a file already opened via `lager:trace_file` will only be
  successful if the same sink is specified.

The former can be ameliorated by opening multiple traces; the latter
can be fixed by rearchitecting lager's file backend, but this has not
been tackled.

571
572
573
Setting the truncation limit at compile-time
--------------------------------------------
Lager defaults to truncating messages at 4096 bytes, you can alter this by
574
575
using the `{lager_truncation_size, X}` option. In rebar, you can add it to
`erl_opts`:
576
577
578
579
580

```erlang
{erl_opts, [{parse_transform, lager_transform}, {lager_truncation_size, 1024}]}.
```

581
You can also pass it to `erlc`, if you prefer:
582
583
584
585

```
erlc -pa lager/ebin +'{parse_transform, lager_transform}' +'{lager_truncation_size, 1024}' file.erl
```
Mark Allen's avatar
Mark Allen committed
586
587
588

3.x Changelog
-------------
Mark Allen's avatar
Mark Allen committed
589
590
591
592
593
594
3.1.0 - 27 January 2016

    * Feature: API calls to a rotate handler, sink or all.  This change
      introduces a new `rotate` message for 3rd party lager backends; that's
      why this is released as a new minor version number. (#311)

Mark Allen's avatar
Mark Allen committed
595
3.0.3 - 27 January 2016
Mark Allen's avatar
Mark Allen committed
596

Mark Allen's avatar
Mark Allen committed
597
598
599
600
601
602
603
604
605
    * Feature: Pretty printer for human readable stack traces (#298)
    * Feature: Make error reformatting optional (#305)
    * Feature: Optional and explicit sink for error_logger messages (#303)
    * Bugfix: Always explicitly close a file after its been rotated (#316)
    * Bugfix: If a relative path already contains the log root, do not add it again (#317)
    * Bugfix: Configure and start extra sinks before traces are evaluated (#307)
    * Bugfix: Stop and remove traces correctly (#306)
    * Bugfix: A byte value of 255 is valid for Unicode (#300)
    * Dependency: Bump to goldrush 0.1.8 (#313)