Merge pull request #120 from basho/adt-msg-has-datetime

Improve the performance of the file backend
diff --git a/.gitignore b/.gitignore
index e04c657..ff8fc4b 100644
--- a/.gitignore
+++ b/.gitignore
@@ -5,3 +5,4 @@
 *.swp
 erl_crash.dump
 .project
+log
diff --git a/.travis.yml b/.travis.yml
index 8a296a2..582c194 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -3,6 +3,8 @@
   webhooks: http://basho-engbot.herokuapp.com/travis?key=8c2550739c2f776d4b05d993aa032f0724fe5450
   email: eng@basho.com
 otp_release:
+  - R16B
+  - R15B03
   - R15B01
   - R15B
   - R14B04
diff --git a/rebar.config b/rebar.config
index a9f18d7..97b3169 100644
--- a/rebar.config
+++ b/rebar.config
@@ -2,4 +2,4 @@
 {erl_first_files, ["src/lager_util.erl"]}.
 
 {cover_enabled, true}.
-{edoc_opts, [{stylesheet_file, "./priv/edoc.css"}]}.
\ No newline at end of file
+{edoc_opts, [{stylesheet_file, "./priv/edoc.css"}]}.
diff --git a/src/lager.app.src b/src/lager.app.src
index 8aaca0e..eed2a6c 100644
--- a/src/lager.app.src
+++ b/src/lager.app.src
@@ -20,6 +20,20 @@
                 {lager_file_backend, [
                     {file, "log/console.log"}, {level, info}, {size, 10485760}, {date, "$D0"}, {count, 5}]}
             ]},
+            %% What colors to use with what log levels
+            {colored, false},
+            {colors, [
+              {debug,     "\e[0;38m" },
+              {info,      "\e[1;37m" },
+              {notice,    "\e[1;36m" },
+              {warning,   "\e[1;33m" },
+              {error,     "\e[1;31m" },
+              {critical,  "\e[1;35m" },
+              {alert,     "\e[1;44m" },
+              {emergency, "\e[1;41m" }
+
+            ]},
+
             %% Whether to write a crash log, and where. Undefined means no crash logger.
             {crash_log, "log/crash.log"},
             %% Maximum size in bytes of events in the crash log - defaults to 65536
diff --git a/src/lager.erl b/src/lager.erl
index abbf99c..eff2e9f 100644
--- a/src/lager.erl
+++ b/src/lager.erl
@@ -20,9 +20,12 @@
 
 -include("lager.hrl").
 
+-define(LAGER_MD_KEY, '__lager_metadata').
+
 %% API
 -export([start/0,
         log/3, log/4,
+        md/0, md/1,
         trace/2, trace/3, trace_file/2, trace_file/3, trace_console/1, trace_console/2,
         clear_all_traces/0, stop_trace/1, status/0,
         get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0,
@@ -51,6 +54,31 @@
 start_ok(App, {error, Reason}) ->
     erlang:error({app_start_failed, App, Reason}).
 
+%% @doc Get lager metadata for current process
+-spec md() -> [{atom(), any()}].
+md() ->
+    case erlang:get(?LAGER_MD_KEY) of
+        undefined -> [];
+        MD -> MD
+    end.
+
+%% @doc Set lager metadata for current process.
+%% Will badarg if you don't supply a list of {key, value} tuples keyed by atoms.
+-spec md([{atom(), any()},...]) -> ok.
+md(NewMD) when is_list(NewMD) ->
+    %% make sure its actually a real proplist
+    case lists:all(
+            fun({Key, _Value}) when is_atom(Key) -> true;
+                (_) -> false
+            end, NewMD) of
+        true ->
+            erlang:put(?LAGER_MD_KEY, NewMD),
+            ok;
+        false ->
+            erlang:error(badarg)
+    end;
+md(_) ->
+    erlang:error(badarg).
 
 -spec dispatch_log(log_level(), list(), string(), list() | none, pos_integer()) ->  ok | {error, lager_not_running}.
 %% this is the same check that the parse transform bakes into the module at compile time
diff --git a/src/lager_app.erl b/src/lager_app.erl
index 8de740c..548e25c 100644
--- a/src/lager_app.erl
+++ b/src/lager_app.erl
@@ -78,11 +78,11 @@
             {ok, false} ->
                 [];
             _ ->
-                case application:get_env(lager, error_logger_whitelist) of
+                WhiteList = case application:get_env(lager, error_logger_whitelist) of
                     undefined ->
-                        WhiteList = [];
-                    {ok, WhiteList} ->
-                        WhiteList
+                        [];
+                    {ok, WhiteList0} ->
+                        WhiteList0
                 end,
 
                 case supervisor:start_child(lager_handler_watcher_sup, [error_logger, error_logger_lager_h, [HighWaterMark]]) of
diff --git a/src/lager_console_backend.erl b/src/lager_console_backend.erl
index 442204a..8f968e0 100644
--- a/src/lager_console_backend.erl
+++ b/src/lager_console_backend.erl
@@ -24,7 +24,7 @@
 -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
         code_change/3]).
 
--record(state, {level, formatter,format_config}).
+-record(state, {level, formatter,format_config,colors=[]}).
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
@@ -32,26 +32,33 @@
 -endif.
 
 -include("lager.hrl").
-
--define(TERSE_FORMAT,[time, " [", severity,"] ", message, "\r\n"]).
+-define(TERSE_FORMAT,[time, " ", color, "[", severity,"] ", message]).
 
 %% @private
 init([Level, true]) -> % for backwards compatibility
-    init([Level,{lager_default_formatter,[{eol, "\r\n"}]}]);
+    init([Level,{lager_default_formatter,[{eol, eol()}]}]);
 init([Level,false]) -> % for backwards compatibility
-    init([Level,{lager_default_formatter,?TERSE_FORMAT}]);
+    init([Level,{lager_default_formatter,?TERSE_FORMAT ++ [eol()]}]);
 init([Level,{Formatter,FormatterConfig}]) when is_atom(Formatter) ->
-   try lager_util:config_to_mask(Level) of
+    Colors = case application:get_env(lager, colored) of
+        {ok, true} -> 
+            {ok, LagerColors} = application:get_env(lager, colors),
+            LagerColors;
+        _ -> []
+    end,
+
+    try lager_util:config_to_mask(Level) of
         Levels ->
             {ok, #state{level=Levels,
                     formatter=Formatter, 
-                    format_config=FormatterConfig}}
+                    format_config=FormatterConfig,
+                    colors=Colors}}
     catch
         _:_ ->
             {error, bad_log_level}
     end;
 init(Level) ->
-    init([Level,{lager_default_formatter,?TERSE_FORMAT}]).
+    init([Level,{lager_default_formatter,?TERSE_FORMAT ++ [eol()]}]).
 
 
 %% @private
@@ -70,10 +77,10 @@
 
 %% @private
 handle_event({log, Message},
-    #state{level=L,formatter=Formatter,format_config=FormatConfig} = State) ->
+    #state{level=L,formatter=Formatter,format_config=FormatConfig,colors=Colors} = State) ->
     case lager_util:is_loggable(Message, L, ?MODULE) of
         true ->
-            io:put_chars(user, Formatter:format(Message,FormatConfig)),
+            io:put_chars(user, Formatter:format(Message,FormatConfig,Colors)),
             {ok, State};
         false ->
             {ok, State}
@@ -93,6 +100,14 @@
 code_change(_OldVsn, State, _Extra) ->
     {ok, State}.
 
+eol() ->
+    case application:get_env(lager, colored) of
+        {ok, true}  ->
+            "\e[0m\r\n";
+        _ -> 
+            "\r\n"
+    end.
+
 -ifdef(TEST).
 console_log_test_() ->
     %% tiny recursive fun that pretends to be a group leader
@@ -131,16 +146,17 @@
             {"regular console logging",
                 fun() ->
                         Pid = spawn(F(self())),
-                        gen_event:add_handler(lager_event, lager_console_backend, info),
                         unregister(user),
                         register(user, Pid),
                         erlang:group_leader(Pid, whereis(lager_event)),
+                        gen_event:add_handler(lager_event, lager_console_backend, info),
                         lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}),
                         lager:log(info, self(), "Test message"),
                         receive
                             {io_request, From, ReplyAs, {put_chars, unicode, Msg}} ->
                                 From ! {io_reply, ReplyAs, ok},
-                                ?assertMatch([_, "[info]", "Test message\r\n"], re:split(Msg, " ", [{return, list}, {parts, 3}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, "[info]", TestMsg], re:split(Msg, " ", [{return, list}, {parts, 3}]))
                         after
                             500 ->
                                 ?assert(false)
@@ -156,11 +172,11 @@
                         gen_event:add_handler(lager_event, lager_console_backend, [info, true]),
                         lager_config:set(loglevel, {element(2, lager_util:config_to_mask(info)), []}),
                         lager:info("Test message"),
-                        lager:info("Test message"),
                         PidStr = pid_to_list(self()),
                         receive
                             {io_request, _, _, {put_chars, unicode, Msg}} ->
-                                ?assertMatch([_, _, "[info]", PidStr, _,"Test message\r\n"], re:split(Msg, "[ @]", [{return, list}, {parts, 6}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, _, "[info]", PidStr, _, TestMsg], re:split(Msg, "[ @]", [{return, list}, {parts, 6}]))
                         after
                             500 ->
                                 ?assert(false)
@@ -183,7 +199,8 @@
                         ModuleStr = atom_to_list(?MODULE),
                         receive
                             {io_request, _, _, {put_chars, unicode, Msg}} ->
-                                ?assertMatch([_, _, "info", NodeStr, PidStr, ModuleStr, _, _, _, "Test message\r\n"], 
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, _, "info", NodeStr, PidStr, ModuleStr, _, _, _, TestMsg], 
                                              re:split(Msg, "#", [{return, list}, {parts, 10}]))
                         after
                             500 ->
@@ -213,7 +230,8 @@
                         receive
                             {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                                 From1 ! {io_reply, ReplyAs1, ok},
-                                ?assertMatch([_, "[debug]", "Test message\r\n"], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
                         after
                             500 ->
                                 ?assert(false)
@@ -242,7 +260,8 @@
                         receive
                             {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                                 From1 ! {io_reply, ReplyAs1, ok},
-                                ?assertMatch([_, "[error]", "Test message\r\n"], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, "[error]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
                         after
                             1000 ->
                                 ?assert(false)
@@ -271,7 +290,8 @@
                         receive
                             {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                                 From1 ! {io_reply, ReplyAs1, ok},
-                                ?assertMatch([_, "[debug]", "Test message\r\n"], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
                         after
                             1000 ->
                                 ?assert(false)
@@ -301,7 +321,8 @@
                         receive
                             {io_request, From1, ReplyAs1, {put_chars, unicode, Msg1}} ->
                                 From1 ! {io_reply, ReplyAs1, ok},
-                                ?assertMatch([_, "[debug]", "Test message\r\n"], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
+                                TestMsg = "Test message" ++ eol(),
+                                ?assertMatch([_, "[debug]", TestMsg], re:split(Msg1, " ", [{return, list}, {parts, 3}]))
                         after
                             1000 ->
                                 ?assert(false)
diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl
index 2e354e0..312f6a0 100644
--- a/src/lager_default_formatter.erl
+++ b/src/lager_default_formatter.erl
@@ -27,7 +27,7 @@
 %%
 %% Exported Functions
 %%
--export([format/2]).
+-export([format/2, format/3]).
 
 %%
 %% API Functions
@@ -53,22 +53,28 @@
 %%
 %%    `[{pid, ["My pid is ", pid], "Unknown Pid"}]' -> if pid is in the metada print "My pid is ?.?.?", otherwise print "Unknown Pid"
 %% @end
--spec format(lager_msg:lager_msg(),list()) -> any().
-format(Msg,[]) ->
-    format(Msg, [{eol, "\n"}]);
-format(Msg,[{eol, EOL}]) ->
+-spec format(lager_msg:lager_msg(),list(),list()) -> any().
+format(Msg,[], Colors) ->
+    format(Msg, [{eol, "\n"}], Colors);
+format(Msg,[{eol, EOL}], Colors) ->
     format(Msg,
-        [date, " ", time, " [", severity, "] ",
+        [date, " ", time, " ", color, "[", severity, "] ",
             {pid, ""},
             {module, [
                     {pid, ["@"], ""},
                     module,
                     {function, [":", function], ""},
                     {line, [":",line], ""}], ""},
-            " ", message, EOL]);
-format(Message,Config) ->
-    [ output(V,Message) || V <- Config ].
+            " ", message, EOL], Colors);
+format(Message,Config,Colors) ->
+    [ case V of
+        color -> output_color(Message,Colors);
+        _ -> output(V,Message) 
+      end || V <- Config ].
 
+-spec format(lager_msg:lager_msg(),list()) -> any().
+format(Msg, Config) ->
+    format(Msg, Config, []).
 
 -spec output(term(),lager_msg:lager_msg()) -> iolist().
 output(message,Msg) -> lager_msg:message(Msg);
@@ -97,6 +103,14 @@
     end;
 output(Other,_) -> make_printable(Other).
 
+output_color(_Msg,[]) -> [];
+output_color(Msg,Colors) ->
+    Level = lager_msg:severity(Msg),
+    case lists:keyfind(Level, 1, Colors) of
+        {_, Color} -> Color;
+        _ -> []
+    end.
+
 -spec make_printable(any()) -> iolist().
 make_printable(A) when is_atom(A) -> atom_to_list(A);
 make_printable(P) when is_pid(P) -> pid_to_list(P);
diff --git a/src/lager_transform.erl b/src/lager_transform.erl
index 30364ee..f610684 100644
--- a/src/lager_transform.erl
+++ b/src/lager_transform.erl
@@ -89,7 +89,9 @@
                         {cons, Line, {tuple, Line, [
                                     {atom, Line, node},
                                     {call, Line, {atom, Line, node}, []}]},
-                         {nil, Line}}}}}},
+                        %% get the metadata with lager:md(), this will always return a list so we can use it as the tail here
+                        {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, md}}, []}}}}}},
+                            %{nil, Line}}}}}}},
             DefaultAttrs = case erlang:get(application) of
                 undefined ->
                     DefaultAttrs0;
@@ -151,7 +153,7 @@
                         [],
                         %% trick the linter into avoiding a 'term constructed by not used' error:
                         %% (fun() -> {error, lager_not_running} end)();
-                        [{call,9, {'fun',9, {clauses, [{clause,9,[],[], [{tuple,9,[{atom,9,error},{atom,9,lager_not_running}]}]}]}}, []}]},
+                        [{call, Line, {'fun', Line, {clauses, [{clause, Line, [],[], [{tuple, Line, [{atom, Line, error},{atom, Line, lager_not_running}]}]}]}}, []}]},
                     %% If we care about the loglevel, or there's any traces installed, we have do more checking
                     %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] ->
                     {clause, Line,
diff --git a/test/lager_test_backend.erl b/test/lager_test_backend.erl
index b29ac8a..e98ccb5 100644
--- a/test/lager_test_backend.erl
+++ b/test/lager_test_backend.erl
@@ -424,6 +424,33 @@
                         ?assertEqual({?DEBUG bor ?INFO bor ?NOTICE bor ?WARNING bor ?ERROR bor ?CRITICAL bor ?ALERT bor ?EMERGENCY, []}, lager_config:get(loglevel)),
                         ok
                 end
+            },
+            {"metadata in the process dictionary works",
+                fun() ->
+                        lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}]),
+                        lager:info("I sing the animal kingdom electric!"),
+                        {_Level, _Time, _Message, Metadata}  = pop(),
+                        ?assertEqual(gravid, proplists:get_value(platypus, Metadata)),
+                        ?assertEqual(hirsute, proplists:get_value(sloth, Metadata)),
+                        ?assertEqual(erroneous, proplists:get_value(duck, Metadata)),
+                        ?assertEqual(undefined, proplists:get_value(eagle, Metadata)),
+                        lager:md([{platypus, gravid}, {sloth, hirsute}, {eagle, superincumbent}]),
+                        lager:info("I sing the animal kingdom dielectric!"),
+                        {_Level2, _Time2, _Message2, Metadata2}  = pop(),
+                        ?assertEqual(gravid, proplists:get_value(platypus, Metadata2)),
+                        ?assertEqual(hirsute, proplists:get_value(sloth, Metadata2)),
+                        ?assertEqual(undefined, proplists:get_value(duck, Metadata2)),
+                        ?assertEqual(superincumbent, proplists:get_value(eagle, Metadata2)),
+                        ok
+                end
+            },
+            {"can't store invalid metadata",
+                fun() ->
+                        ?assertEqual(ok, lager:md([{platypus, gravid}, {sloth, hirsute}, {duck, erroneous}])),
+                        ?assertError(badarg, lager:md({flamboyant, flamingo})),
+                        ?assertError(badarg, lager:md("zookeeper zephyr")),
+                        ok
+                end
             }
         ]
     }.