Roll 2.2.3

Support typed records newly exposed in OTP 19

Reviewed-by: macintux

README.md

@@ -420,3 +420,17 @@ You can also pass it to `erlc`, if you prefer:
 ```
 erlc -pa lager/ebin +'{parse_transform, lager_transform}' +'{lager_truncation_size, 1024}' file.erl
 ```
+
+Changelog 2.x
+-------------
+2.2.3 - 10 June 2016
+    * OTP: Support typed records for Erlang 19.0 (#361)
+
+2.2.2 - 08 April 2016
+    * Bugfix: Field name for processes changed from 'name' to 'id' in 2014. (#339)
+    * Bugfix: OTP 18 test failure fixes. (#338)
+
+2.2.1 - 27 January 2016
+    * Dependency: Bump goldrush to 0.1.8
+    * Bugfix: Properly remove backends from traces when stopped. (#308)
+    * Bugfix: Handle byte value 255 (0xFF) properly (#292)

rebar.config

@@ -1,9 +1,33 @@
-{erl_opts, [debug_info, warn_untyped_record]}.
+%% -*- erlang -*-
+%% -------------------------------------------------------------------
+%%
+%% Copyright (c) 2011-2015 Basho Technologies, Inc.
+%%
+%% 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.
+%%
+%% -------------------------------------------------------------------
+
 {erl_first_files, ["src/lager_util.erl"]}.
+
+{erl_opts, [
+    debug_info,
+    warn_untyped_record
+]}.
 {deps, [
-        {goldrush, "0\.1\.6",
-            {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.6"}}}
-       ]}.
+    {goldrush, ".*", {git, "git://github.com/DeadZen/goldrush.git", {tag, "0.1.8"}}}
+]}.
 
 {xref_checks, []}.
 {xref_queries, [{"(XC - UC) || (XU - X - B - lager_default_tracer : Mod - erlang:\"(is_map|map_size)\"/1 - maps:to_list/1)", []}]}.

src/error_logger_lager_h.erl

@@ -197,7 +197,7 @@ log_event(Event, State) ->
                     ?LOGFMT(error, Pid, "Webmachine error at path ~p : ~s", [Path, format_reason(StackTrace)]);
                 _ ->
                     ?CRASH_LOG(Event),
-                    ?LOGMSG(error, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION))
+                    ?LOGFMT(error, Pid, Fmt, Args)
             end;
         {error_report, _GL, {Pid, std_error, D}} ->
             ?CRASH_LOG(Event),
@@ -217,11 +217,11 @@ log_event(Event, State) ->
             ?CRASH_LOG(Event),
             ?LOGMSG(error, Pid, "CRASH REPORT " ++ format_crash_report(Self, Neighbours));
         {warning_msg, _GL, {Pid, Fmt, Args}} ->
-            ?LOGMSG(warning, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION));
+            ?LOGFMT(warning, Pid, Fmt, Args);
         {warning_report, _GL, {Pid, std_warning, Report}} ->
             ?LOGMSG(warning, Pid, print_silly_list(Report));
         {info_msg, _GL, {Pid, Fmt, Args}} ->
-            ?LOGMSG(info, Pid, lager:safe_format(Fmt, Args, ?DEFAULT_TRUNCATION));
+            ?LOGFMT(info, Pid, Fmt, Args);
         {info_report, _GL, {Pid, std_info, D}} when is_list(D) ->
             Details = lists:sort(D),
             case Details of
@@ -287,7 +287,15 @@ format_offender(Off) ->
         MFArgs ->
             %% regular supervisor
             MFA = format_mfa(MFArgs),
-            Name = get_value(name, Off),
+
+            %% In 2014 the error report changed from `name' to
+            %% `id', so try that first.
+            Name = case get_value(id, Off) of
+                       undefined ->
+                           get_value(name, Off);
+                       Id ->
+                           Id
+                   end,
             io_lib:format("~p started with ~s at ~w",
                 [Name, MFA, get_value(pid, Off)])
     end.

src/lager.app.src

@@ -3,7 +3,7 @@
 {application, lager,
  [
   {description, "Erlang logging framework"},
-  {vsn, "2.1.1"},
+  {vsn, "2.2.3"},
   {modules, []},
   {applications, [
                   kernel,

src/lager.erl

@@ -210,7 +210,16 @@ stop_trace(Backend, Filter, Level) ->
 stop_trace({Backend, Filter, Level}) ->
     stop_trace(Backend, Filter, Level).
 
-stop_trace_int({Backend, _Filter, _Level} = Trace) ->
+%% Important: validate_trace_filters orders the arguments of
+%% trace tuples differently than the way outside callers have
+%% the trace tuple.
+%%
+%% That is to say, outside they are represented as 
+%% `{Backend, Filter, Level}'
+%%
+%% and when they come back from validation, they're
+%% `{Filter, Level, Backend}'
+stop_trace_int({_Filter, _Level, Backend} = Trace) ->
     {Level, Traces} = lager_config:get(loglevel),
     NewTraces =  lists:delete(Trace, Traces),
     _ = lager_util:trace_filter([ element(1, T) || T <- NewTraces ]),

src/lager_backend_throttle.erl

@@ -29,6 +29,17 @@
 -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
         code_change/3]).
 
+%%
+%% Allow test code to verify that we're doing the needful.
+-ifdef(TEST).
+-define(ETS_TABLE, async_threshold_test).
+-define(TOGGLE_SYNC(), test_increment(sync_toggled)).
+-define(TOGGLE_ASYNC(), test_increment(async_toggled)).
+-else.
+-define(TOGGLE_SYNC(), true).
+-define(TOGGLE_ASYNC(), true).
+-endif.
+
 -record(state, {
         hwm :: non_neg_integer(),
         window_min :: non_neg_integer(),
@@ -52,10 +63,12 @@ handle_event({log, _Message},State) ->
     case {Len > State#state.hwm, Len < State#state.window_min, State#state.async} of
         {true, _, true} ->
             %% need to flip to sync mode
+            ?TOGGLE_SYNC(),
             lager_config:set(async, false),
             {ok, State#state{async=false}};
         {_, true, false} ->
             %% need to flip to async mode
+            ?TOGGLE_ASYNC(),
             lager_config:set(async, true),
             {ok, State#state{async=true}};
         _ ->
@@ -76,3 +89,16 @@ terminate(_Reason, _State) ->
 code_change(_OldVsn, State, _Extra) ->
     {ok, State}.
 
+-ifdef(TEST).
+test_get(Key) ->
+    get_default(ets:lookup(?ETS_TABLE, Key)).
+
+test_increment(Key) ->
+    ets:insert(?ETS_TABLE,
+               {Key, test_get(Key) + 1}).
+
+get_default([]) ->
+    0;
+get_default([{_Key, Value}]) ->
+    Value.
+-endif.

src/lager_file_backend.erl

@@ -728,6 +728,11 @@ filesystem_test_() ->
                         {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}], [{size, 20}, {check_interval, 1}]), 
                         lager:error("Test message"),
                         ?assertNot(filelib:is_regular("foo.log.0")),
+                        %% rotation is sensitive to intervals between
+                        %% writes so we sleep to exceed the 1
+                        %% millisecond interval specified by
+                        %% check_interval above
+                        timer:sleep(2),
                         lager:error("Test message"),
                         timer:sleep(10),
                         ?assert(filelib:is_regular("foo.log.0"))

src/lager_stdlib.erl

@@ -39,7 +39,7 @@ string_p([]) ->
 string_p(Term) ->
     string_p1(Term).
 
-string_p1([H|T]) when is_integer(H), H >= $\s, H < 255 ->
+string_p1([H|T]) when is_integer(H), H >= $\s, H < 256 ->
     string_p1(T);
 string_p1([$\n|T]) -> string_p1(T);
 string_p1([$\r|T]) -> string_p1(T);

src/lager_transform.erl

@@ -57,16 +57,19 @@ walk_ast(Acc, [{function, Line, Name, Arity, Clauses}|T]) ->
     walk_ast([{function, Line, Name, Arity,
                 walk_clauses([], Clauses)}|Acc], T);
 walk_ast(Acc, [{attribute, _, record, {Name, Fields}}=H|T]) ->
-    FieldNames = lists:map(fun({record_field, _, {atom, _, FieldName}}) ->
-                FieldName;
-            ({record_field, _, {atom, _, FieldName}, _Default}) ->
-                FieldName
-        end, Fields),
+    FieldNames = lists:map(fun record_field_name/1, Fields),
     stash_record({Name, FieldNames}),
     walk_ast([H|Acc], T);
 walk_ast(Acc, [H|T]) ->
     walk_ast([H|Acc], T).
 
+record_field_name({record_field, _, {atom, _, FieldName}}) ->
+    FieldName;
+record_field_name({record_field, _, {atom, _, FieldName}, _Default}) ->
+    FieldName;
+record_field_name({typed_record_field, Field, _Type}) ->
+    record_field_name(Field).
+
 walk_clauses(Acc, []) ->
     lists:reverse(Acc);
 walk_clauses(Acc, [{clause, Line, Arguments, Guards, Body}|T]) ->

test/crash.erl

@@ -10,8 +10,8 @@
 -export([start/0]).
 
 -record(state, {
-        host,
-        port
+        host :: term(),
+        port :: term()
     }).
 
 start() ->

test/lager_test_backend.erl

@@ -1,4 +1,6 @@
-%% Copyright (c) 2011-2012 Basho Technologies, Inc.  All Rights Reserved.
+%% -------------------------------------------------------------------
+%%
+%% Copyright (c) 2011-2015 Basho Technologies, Inc.
 %%
 %% This file is provided to you under the Apache License,
 %% Version 2.0 (the "License"); you may not use this file
@@ -13,6 +15,8 @@
 %% KIND, either express or implied.  See the License for the
 %% specific language governing permissions and limitations
 %% under the License.
+%%
+%% -------------------------------------------------------------------
 
 -module(lager_test_backend).
 
@@ -23,8 +27,8 @@
 -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
         code_change/3]).
 
--record(state, {level, buffer, ignored}).
--record(test, {attrs, format, args}).
+-record(state, {level :: list(), buffer :: list(), ignored :: list()}).
+-record(test, {attrs :: term(), format :: term() , args :: term()}).
 -compile([{parse_transform, lager_transform}]).
 
 -ifdef(TEST).
@@ -108,9 +112,25 @@ print_bad_state() ->
 
 has_line_numbers() ->
     %% are we R15 or greater
-    Rel = erlang:system_info(otp_release),
-    {match, [Major]} = re:run(Rel, "(?|(^R(\\d+)[A|B](|0(\\d)))|(^(\\d+)$))", [{capture, [2], list}]),
-    list_to_integer(Major) >= 15.
+    % this gets called a LOT - cache the answer
+    case erlang:get({?MODULE, has_line_numbers}) of
+        undefined ->
+            R = otp_version() >= 15,
+            erlang:put({?MODULE, has_line_numbers}, R),
+            R;
+        Bool ->
+            Bool
+    end.
+
+otp_version() ->
+    otp_version(erlang:system_info(otp_release)).
+
+otp_version([$R | Rel]) ->
+    {Ver, _} = string:to_integer(Rel),
+    Ver;
+otp_version(Rel) ->
+    {Ver, _} = string:to_integer(Rel),
+    Ver.
 
 not_running_test() ->
     ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).
@@ -469,6 +489,24 @@ lager_test_() ->
                         ok
                 end
             },
+            {"stopped trace stops and removes its event handler (gh#267)",
+                fun() ->
+                        StartHandlers = gen_event:which_handlers(lager_event),
+                        {_, T0} = lager_config:get(loglevel),
+                        ?assertEqual([], T0),
+                        {ok, Test} = lager:trace_file("/tmp/test", [{vhost, test}]),
+                        MidHandlers = gen_event:which_handlers(lager_event),
+                        ?assertEqual(length(StartHandlers)+1, length(MidHandlers)),
+                        {_, T1} = lager_config:get(loglevel),
+                        ?assertEqual(1, length(T1)),
+                        ok = lager:stop_trace(Test),
+                        {_, T2} = lager_config:get(loglevel),
+                        ?assertEqual([], T2),
+                        EndHandlers = gen_event:which_handlers(lager_event),
+                        ?assertEqual(StartHandlers, EndHandlers),
+                        ok
+                end
+            },
             {"record printing works",
                 fun() ->
                         print_state(),
@@ -579,20 +617,42 @@ crash(Type) ->
 test_body(Expected, Actual) ->
     case has_line_numbers() of
         true ->
-            FileLine = string:substr(Actual, length(Expected)+1),
-            Body = string:substr(Actual, 1, length(Expected)),
+            ExLen = length(Expected),
+            {Body, Rest} = case length(Actual) > ExLen of
+                true ->
+                    {string:substr(Actual, 1, ExLen),
+                        string:substr(Actual, (ExLen + 1))};
+                _ ->
+                    {Actual, []}
+            end,
             ?assertEqual(Expected, Body),
-            case string:substr(FileLine, 1, 6) of
+            % OTP-17 (and maybe later releases) may tack on additional info
+            % about the failure, so if Actual starts with Expected (already
+            % confirmed by having gotten past assertEqual above) and ends
+            % with " line NNN" we can ignore what's in-between. By extension,
+            % since there may not be line information appended at all, any
+            % text we DO find is reportable, but not a test failure.
+            case Rest of
                 [] ->
-                    %% sometimes there's no line information...
-                    ?assert(true);
-                " line " ->
-                    ?assert(true);
-                Other ->
-                    ?debugFmt("unexpected trailing data ~p", [Other]),
-                    ?assert(false)
+                    ok;
+                _ ->
+                    % isolate the extra data and report it if it's not just
+                    % a line number indicator
+                    case re:run(Rest, "^.*( line \\d+)$", [{capture, [1]}]) of
+                        nomatch ->
+                            ?debugFmt(
+                                "Trailing data \"~s\" following \"~s\"",
+                                [Rest, Expected]);
+                        {match, [{0, _}]} ->
+                            % the whole sting is " line NNN"
+                            ok;
+                        {match, [{Off, _}]} ->
+                            ?debugFmt(
+                                "Trailing data \"~s\" following \"~s\"",
+                                [string:substr(Rest, 1, Off), Expected])
+                    end
             end;
-        false ->
+        _ ->
             ?assertEqual(Expected, Actual)
     end.
 
@@ -607,7 +667,7 @@ error_logger_redirect_crash_test_() ->
                         ?assertEqual(Pid,proplists:get_value(pid,Metadata)),
                         ?assertEqual(lager_util:level_to_num(error),Level)
                 end
-            } 
+            }
     end,
     {foreach,
         fun() ->
@@ -709,6 +769,17 @@ error_logger_redirect_test_() ->
                         ?assertEqual(Expected, lists:flatten(Msg))
                 end
             },
+            {"error messages with unicode characters in Args are printed",
+                fun() ->
+                        sync_error_logger:error_msg("~ts", ["Привет!"]),
+                        _ = gen_event:which_handlers(error_logger),
+                        {Level, _, Msg,Metadata} = pop(),
+                        ?assertEqual(lager_util:level_to_num(error),Level),
+                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
+                        ?assertEqual("Привет!", lists:flatten(Msg))
+                end
+            },
+
             {"error messages are truncated at 4096 characters",
                 fun() ->
                         sync_error_logger:error_msg("doom, doom has come upon you all ~p", [string:copies("doom", 10000)]),
@@ -808,36 +879,70 @@ error_logger_redirect_test_() ->
                         ?assert(length(lists:flatten(Msg)) < 5100)
                 end
             },
+            {"info messages with unicode characters in Args are printed",
+                fun() ->
+                        sync_error_logger:info_msg("~ts", ["Привет!"]),
+                        _ = gen_event:which_handlers(error_logger),
+                        {Level, _, Msg,Metadata} = pop(),
+                        ?assertEqual(lager_util:level_to_num(info),Level),
+                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
+                        ?assertEqual("Привет!", lists:flatten(Msg))
+                end
+            },
+            {"warning messages with unicode characters in Args are printed",
+             %% See comments at commit 7662a8040d5427907c041ca8e682fe09f6f17d26
+             %% for full details of why using the process dictionary is needed
+             %% for these next 4 tests.
+             %%
+             %% In short, the error level atom used in OTP releases changed
+             %% between 17 and 18 and the default used in sync_error_logger
+             %% isn't right for OTP 18 and later. Storing the expected level
+             %% in the process dictionary makes sync_error_logger use the
+             %% correct level when processing the log messages.
+                fun() ->
+                        Lvl = error_logger:warning_map(),
+                        put(warning_map, Lvl),
+                        sync_error_logger:warning_msg("~ts", ["Привет!"]),
+                        _ = gen_event:which_handlers(error_logger),
+                        {Level, _, Msg,Metadata} = pop(),
+                        ?assertEqual(lager_util:level_to_num(Lvl),Level),
+                        ?assertEqual(self(),proplists:get_value(pid,Metadata)),
+                        ?assertEqual("Привет!", lists:flatten(Msg))
+                end
+            },
 
             {"warning messages are printed at the correct level",
                 fun() ->
+                        Lvl = error_logger:warning_map(),
+                        put(warning_map, Lvl),
                         sync_error_logger:warning_msg("doom, doom has come upon you all"),
-                        Map = error_logger:warning_map(),
                         _ = gen_event:which_handlers(error_logger),
                         {Level, _, Msg,Metadata} = pop(),
-                        ?assertEqual(lager_util:level_to_num(Map),Level),
+                        ?assertEqual(lager_util:level_to_num(Lvl),Level),
                         ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                         ?assertEqual("doom, doom has come upon you all", lists:flatten(Msg))
                 end
             },
             {"warning reports are printed at the correct level",
                 fun() ->
+                        Lvl = error_logger:warning_map(),
+                        put(warning_map, Lvl),
                         sync_error_logger:warning_report([{i, like}, pie]),
-                        Map = error_logger:warning_map(),
                         _ = gen_event:which_handlers(error_logger),
                         {Level, _, Msg,Metadata} = pop(),
-                        ?assertEqual(lager_util:level_to_num(Map),Level),
+                        ?assertEqual(lager_util:level_to_num(Lvl),Level),
                         ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                         ?assertEqual("i: like, pie", lists:flatten(Msg))
                 end
             },
             {"single term warning reports are printed at the correct level",
                 fun() ->
+                        Lvl = error_logger:warning_map(),
+                        put(warning_map, Lvl),
                         sync_error_logger:warning_report({foolish, bees}),
-                        Map = error_logger:warning_map(),
                         _ = gen_event:which_handlers(error_logger),
                         {Level, _, Msg,Metadata} = pop(),
-                        ?assertEqual(lager_util:level_to_num(Map),Level),
+                        ?assertEqual(lager_util:level_to_num(Lvl),Level),
                         ?assertEqual(self(),proplists:get_value(pid,Metadata)),
                         ?assertEqual("{foolish,bees}", lists:flatten(Msg))
                 end
@@ -1004,7 +1109,7 @@ error_logger_redirect_test_() ->
                         ?assert(length(lists:flatten(Msg)) < 600)
                 end
             },
-            {"crash reports for 'special processes' should be handled right - function_clause", 
+            {"crash reports for 'special processes' should be handled right - function_clause",
                 fun() ->
                         {ok, Pid} = special_process:start(),
                         unlink(Pid),
@@ -1017,7 +1122,7 @@ error_logger_redirect_test_() ->
                         test_body(Expected, lists:flatten(Msg))
                 end
             },
-            {"crash reports for 'special processes' should be handled right - case_clause", 
+            {"crash reports for 'special processes' should be handled right - case_clause",
                 fun() ->
                         {ok, Pid} = special_process:start(),
                         unlink(Pid),
@@ -1030,7 +1135,7 @@ error_logger_redirect_test_() ->
                         test_body(Expected, lists:flatten(Msg))
                 end
             },
-            {"crash reports for 'special processes' should be handled right - exit", 
+            {"crash reports for 'special processes' should be handled right - exit",
                 fun() ->
                         {ok, Pid} = special_process:start(),
                         unlink(Pid),
@@ -1043,7 +1148,7 @@ error_logger_redirect_test_() ->
                         test_body(Expected, lists:flatten(Msg))
                 end
             },
-            {"crash reports for 'special processes' should be handled right - error", 
+            {"crash reports for 'special processes' should be handled right - error",
                 fun() ->
                         {ok, Pid} = special_process:start(),
                         unlink(Pid),
@@ -1159,6 +1264,9 @@ async_threshold_test_() ->
     {foreach,
         fun() ->
                 error_logger:tty(false),
+                ets:new(async_threshold_test, [set, named_table, public]),
+                ets:insert_new(async_threshold_test, {sync_toggled, 0}),
+                ets:insert_new(async_threshold_test, {async_toggled, 0}),
                 application:load(lager),
                 application:set_env(lager, error_logger_redirect, false),
                 application:set_env(lager, async_threshold, 2),
@@ -1170,6 +1278,7 @@ async_threshold_test_() ->
                 application:unset_env(lager, async_threshold),
                 application:stop(lager),
                 application:stop(goldrush),
+                ets:delete(async_threshold_test),
                 error_logger:tty(true)
         end,
         [
@@ -1184,11 +1293,22 @@ async_threshold_test_() ->
                         %% serialize on mailbox
                         _ = gen_event:which_handlers(lager_event),
                         timer:sleep(500),
-                        %% there should be a ton of outstanding messages now, so async is false
-                        ?assertEqual(false, lager_config:get(async)),
-                        %% wait for all the workers to return, meaning that all the messages have been logged (since we're in sync mode)
+
+                        %% By now the flood of messages will have
+                        %% forced the backend throttle to turn off
+                        %% async mode, but it's possible all
+                        %% outstanding requests have been processed,
+                        %% so checking the current status (sync or
+                        %% async) is an exercise in race control.
+
+                        %% Instead, we'll see whether the backend
+                        %% throttle has toggled into sync mode at any
+                        %% point in the past
+                        ?assertMatch([{sync_toggled, N}] when N > 0,
+                                                              ets:lookup(async_threshold_test, sync_toggled)),
+                        %% wait for all the workers to return, meaning that all the messages have been logged (since we're definitely in sync mode at the end of the run)
                         collect_workers(Workers),
-                        %% serialize ont  the mailbox again
+                        %% serialize on the mailbox again
                         _ = gen_event:which_handlers(lager_event),
                         %% just in case...
                         timer:sleep(1000),

test/pr_nested_record_test.erl

@@ -2,13 +2,11 @@
 
 -compile([{parse_transform, lager_transform}]).
 
--record(a, {field1, field2}).
--record(b, {field1, field2}).
+-record(a, {field1 :: term(), field2 :: term()}).
+-record(b, {field1 :: term() , field2 :: term()}).
 
 
--ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
--endif.
 
 nested_record_test() ->
     A = #a{field1 = x, field2 = y}, 

test/trunc_io_eqc.erl

@@ -91,7 +91,7 @@ gen_fmt_args() ->
 
 %% Generates a printable string
 gen_print_str() ->
-    ?LET(Xs, list(char()), [X || X <- Xs, io_lib:printable_list([X]), X /= $~, X < 255]).
+    ?LET(Xs, list(char()), [X || X <- Xs, io_lib:printable_list([X]), X /= $~, X < 256]).
 
 gen_print_bin() ->
     ?LET(Xs, gen_print_str(), list_to_binary(Xs)).