Previously the following configuration didn't work properly:
{log_root, "logs"},
{handlers, [{lager_file_backend, [{file, "access.log"}, {level, none}, ...]}]},
{traces, [{{lager_file_backend, "access.log"}, [{tag, access}], info}]}
When lager:trace_file was trying to find a file among the existing
handlers, it was searching for the expanded file name
("logs/access.log"), but the handlers store the file names without
expansion ("access.log"), so it didn't find it.
The result was that lager:trace_file started another "access.log"
backend, which of course didn't use e.g. the log rotation settings of
the first handler. When the log_root was relative, then each log
message appeared twice in the log file (both backends thought that they
should log it, because when calculating the Destination,
"logs/access.log" was used in both cases).
Now the code performs path expansion on the file name inside the handler
too. Also, now it calculates the absolute paths of both files, so that
if one file is specified with an absolute path and the other with a
relative path, lager will still know that they are the same.
Test
----
Using the old code (tag 3.2.4 was tested) the new test usually fails the
following way:
module 'lager_trace_test'
lager_trace_test: trace_test_ (Trace combined with log_root)...*failed*
in function lager_trace_test:'-trace_test_/0-fun-6-'/0 (test/lager_trace_test.erl, line 71)
**throw:{too_many_entries,{ok,<<"Test message\n2017-03-26 23:04:23.935 [info] <0.5898.0>@lager"...>>}}
output:<<"">>
The reason for failing only usually is that it might happen that the
duplicate log entry is added to file only after we called
time:sleep(1000) and checked that the log entry is not there.
Previously, error_logger messages only had the pid of the crashed
process, not any of the traditional lager metadata like
module, function, line, etc.
It turns out, however, that we already have most if not all of that
information as metadata already in the stack trace. Thus, we can capture
it and re-inject the error logger log message as a lager message with
metadata.
Additionally, when a process crashes, we get the process dictionary
passed to us, which we can scan for the '_lager_metadata' entry, and
attach the dead process' metadata to the log message as well.
On final analysis, it appears the effective fix is clearing out leftover lager state in the application controller.
Along the way, the test body was modified to account for the runtime system, and as this doesn't seem like a bad thing it's left in place.
This commit also moves `otp_version/0` to `lager_util`'s public API, as it may be helpful in future tests that check for version-specific messages (see issue #383).
Uses lager_util:create_test_dir/0 and lager_util:delete_test_dir/1 to give tests, or groups thereof, their own clean directory to work in.
Turn off whitespace diffs to review, as much code is shifted left to allow sane wrapping within around 100 columns.
Change rotate_file_test/0 and rotate_file_fail_test/0 to use temporary test directories.
Refactor rotate_file_test/0 to be marginally understandable.
Fix rotate_file_fail_test/0 to use 'chmod', as intended, instead of 'chown'.
This allows users to log metadata (tuple list) without a format string in lager. For
example `lager:info([{foo, bar}])` instead of `lager:info([{foo,bar}], "")`.
Add `| undefined` to records that get initialized with not all their
fields set to the proper type (hence get the value undefined). These
fixes allow lager to exist as a dependency in a project and be filtered
through that project's dialyzer run without warnings.
The strict configuration work in 31cf6c0 prevents some
backwards-compatible code in lager_file_backend from working as the
configuration is rejected before it gets to the backend. This fix adds
an additional guard on `check_handler_config/2` to support the `tuple`
configuration structure supported by `lager_file_backend`.
Applications that explicitly configure lager's `crash_log` with the
value `undefined` will get a really terrible crash message for all
versions since 81222ca486
Diff here: 81222ca486 (diff-25e915f0df09d04052d2a6e85b8824f2)
That message looks like this:
```
** Generic server lager_crash_log terminating
** Last message in was rotate
** When Server state == {state,undefined,
{file_descriptor,prim_file,{#Port<0.1340>,15}},
281571,65536,10485760,
[{hour,0}],
5,false}
** Reason for termination ==
** {badarg,[{erlang,'++',[undefined,".3"],[]},
{lager_util,rotate_logfile,2,
[{file,"_build/default/lib/lager/src/lager_util.erl"},
{line,220}]},
{lager_crash_log,handle_info,2,
[{file,"_build/default/lib/lager/src/lager_crash_log.erl"},
{line,99}]},
{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,601}]},
{gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,667}]},
{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}
```
This fix will allow people who use this legacy configuration to not
experience production crashes at midnight after the deploy, when
crash_log tries to rotate for the very first time, resulting in trying
to append `.Int` to `undefined`
* Make lager_handler_watcher test more resilient by scanning for
messages of interest rather than assuming we know exactly what
messages will arrive at the test backend
Lager logs its own application start up message. Previously
this message was discarded or not received quickly enough
to cause test failures, but now it seems as though it
is being received and causing several test failures
even though we are explicitly flushing it away.
We introduce a 5 millisecond sleep for several tests
to make sure the start up message is received before the
flush command dumps it.
Previously, configuration would come from application:get_env/3 or
proplists:get_value/3. Now we standardize on a single format
for retrieving values from the environment or from a proplist.
This is, perhaps, not the most ideal setup. It still ignores other
sinks but does bring logging back online after the appropriate delay.
Signed-off-by: Brian L. Troutwine <brian.troutwine@adroll.com>
At this point in the work, the killer will correctly stop the
DEFAULT_SINK in the event of overload but our friend never comes back
up and lager stops working past this point.
Oops!
Error message:
=SUPERVISOR REPORT==== 10-Mar-2016::16:18:11 ===
Supervisor: {local,lager_handler_watcher_sup}
Context: child_terminated
Reason: killed
Offender: [{pid,<0.63.0>},
{id,lager_handler_watcher},
{mfargs,{lager_handler_watcher,start_link,undefined}},
{restart_type,temporary},
{shutdown,5000},
{child_type,worker}]
=SUPERVISOR REPORT==== 10-Mar-2016::16:18:11 ===
Supervisor: {local,lager_handler_watcher_sup}
Context: child_terminated
Reason: killed
Offender: [{pid,<0.59.0>},
{id,lager_handler_watcher},
{mfargs,{lager_handler_watcher,start_link,undefined}},
{restart_type,temporary},
{shutdown,5000},
{child_type,worker}]
=PROGRESS REPORT==== 10-Mar-2016::16:18:11 ===
supervisor: {local,lager_sup}
started: [{pid,<0.113.0>},
{id,lager},
{mfargs,{gen_event,start_link,[{local,lager_event}]}},
{restart_type,permanent},
{shutdown,5000},
{child_type,worker}]
Signed-off-by: Brian L. Troutwine <brian@troutwine.us>
Address #286. This will enable applications to
dynamically configure log sinks, provided they
have already instrumented the code via parse
transformation to use those sinks.
Lager logs its own application start up message. Previously
this message was discarded or not received quickly enough
to cause test failures, but now it seems as though it
is being received and causing several test failures
even though we are explicitly flushing it away.
We introduce a 5 millisecond sleep for several tests
to make sure the start up message is received before the
flush command dumps it.
Previously, configuration would come from application:get_env/3 or
proplists:get_value/3. Now we standardize on a single format
for retrieving values from the environment or from a proplist.