Record milliseconds with timestamps, make console less verbose by default

az558

src/lager.erl

@@ -53,7 +53,7 @@ start_ok(App, {error, Reason}) ->
     ok | {error, lager_not_running}.
 log(Level, Module, Function, Line, Pid, Time, Message) ->
     Timestamp = lager_util:format_time(Time),
-    Msg = [io_lib:format("[~p] ~p@~p:~p:~p ", [Level, Pid, Module,
+    Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module,
                 Function, Line]),  string:strip(lists:flatten(Message), right, $\n)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
@@ -62,7 +62,7 @@ log(Level, Module, Function, Line, Pid, Time, Message) ->
     ok | {error, lager_not_running}.
 log(Level, Module, Function, Line, Pid, Time, Format, Args) ->
     Timestamp = lager_util:format_time(Time),
-    Msg = [io_lib:format("[~p] ~p@~p:~p:~p ", [Level, Pid, Module,
+    Msg = [["[", atom_to_list(Level), "] "], io_lib:format("~p@~p:~p:~p ", [Pid, Module,
                 Function, Line]), string:strip(lists:flatten(io_lib:format(Format, Args)), right, $\n)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
@@ -70,14 +70,14 @@ log(Level, Module, Function, Line, Pid, Time, Format, Args) ->
 -spec log(log_level(), pid(), list()) -> ok | {error, lager_not_running}.
 log(Level, Pid, Message) ->
     Timestamp = lager_util:format_time(),
-    Msg = [io_lib:format("[~p] ~p ", [Level, Pid]), string:strip(lists:flatten(Message), right, $\n)],
+    Msg = [["[", atom_to_list(Level), "] "], [pid_to_list(Pid), " "], string:strip(lists:flatten(Message), right, $\n)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
 %% @doc Manually log a message into lager without using the parse transform.
 -spec log(log_level(), pid(), string(), list()) -> ok | {error, lager_not_running}.
 log(Level, Pid, Format, Args) ->
     Timestamp = lager_util:format_time(),
-    Msg = [io_lib:format("[~p] ~p ", [Level, Pid]), string:strip(lists:flatten(io_lib:format(Format, Args)), right, $\n)],
+    Msg = [["[", atom_to_list(Level), "] "], [pid_to_list(Pid), " "], string:strip(lists:flatten(io_lib:format(Format, Args)), right, $\n)],
     safe_notify(lager_util:level_to_num(Level), Timestamp, Msg).
 
 %% @doc Set the loglevel for a particular backend.

src/lager_console_backend.erl

@@ -24,11 +24,13 @@
 -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
         code_change/3]).
 
--record(state, {level}).
+-record(state, {level, verbose}).
 
 %% @private
-init(Level) ->
-    {ok, #state{level=lager_util:level_to_num(Level)}}.
+init(Level) when is_atom(Level) ->
+    {ok, #state{level=lager_util:level_to_num(Level), verbose=false}};
+init([Level, Verbose]) ->
+    {ok, #state{level=lager_util:level_to_num(Level), verbose=Verbose}}.
 
 %% @private
 handle_call(get_loglevel, #state{level=Level} = State) ->
@@ -39,8 +41,13 @@ handle_call(_Request, State) ->
     {ok, ok, State}.
 
 %% @private
-handle_event({log, Level, Time, Message}, #state{level=LogLevel} = State) when Level =< LogLevel ->
-    io:put_chars([Time, " ", Message, "\n"]),
+handle_event({log, Level, {Date, Time}, [LevelStr, Location, Message]}, #state{level=LogLevel, verbose=Verbose} = State) when Level =< LogLevel ->
+    case Verbose of
+        true ->
+            io:put_chars([Date, " ", Time, " ", LevelStr, Location, Message, "\n"]);
+        _ ->
+            io:put_chars([Time, " ", LevelStr, Message, "\n"])
+    end,
     {ok, State};
 handle_event(_Event, State) ->
     {ok, State}.

src/lager_crash_log.erl

@@ -79,9 +79,8 @@ handle_cast({log, Event}, #state{name=Name, fd=FD, inode=Inode, flap=Flap, fmtma
         true ->
             case lager_util:ensure_logfile(Name, FD, Inode, false) of
                 {ok, {NewFD, NewInode}} ->
-                    Time = [lager_util:format_time(
-                            lager_stdlib:maybe_utc(erlang:localtime())),
-                        " =", ReportStr, "====\n"],
+                    {Date, TS} = lager_util:format_time(lager_stdlib:maybe_utc(erlang:localtime())),
+                    Time = [Date, " ", TS," =", ReportStr, "====\n"],
                     NodeSuffix = other_node_suffix(Pid),
                     case file:write(NewFD, io_lib:format("~s~s~s", [Time, MsgStr, NodeSuffix])) of
                         {error, Reason} when Flap == false ->

src/lager_file_backend.erl

@@ -87,10 +87,10 @@ handle_call(_Request, State) ->
     {ok, ok, State}.
 
 %% @private
-handle_event({log, Level, Time, Message}, #state{files=Files} = State) ->
+handle_event({log, Level, {Date, Time}, Message}, #state{files=Files} = State) ->
     NewFiles = lists:map(
         fun(#file{level=L} = File) when Level =< L ->
-                write(File, Level, [Time, " ", Message, "\n"]);
+                write(File, Level, [Date, " ", Time, " ", Message, "\n"]);
             (File) ->
                 File
         end, Files),

src/lager_transform.erl

@@ -80,11 +80,11 @@ transform_statement({call, Line, {remote, Line1, {atom, Line2, lager},
                                         {integer, Line3, Line},
                                         {call, Line3, {atom, Line3 ,self}, []},
                                         {call, Line3, {remote, Line3,
-                                                {atom, Line3 ,lager_stdlib},
+                                                {atom, Line3 ,lager_util},
                                                 {atom,Line3,maybe_utc}},
                                             [{call,Line3,{remote,Line3,
-                                                        {atom,Line3,erlang},
-                                                        {atom,Line3,localtime}},[]}]}
+                                                        {atom,Line3,lager_util},
+                                                        {atom,Line3,localtime_ms}},[]}]}
                                         | Arguments
                                     ]}]},
                         %% No, don't log

src/lager_util.erl

@@ -19,7 +19,7 @@
 -include_lib("kernel/include/file.hrl").
 
 -export([levels/0, level_to_num/1, num_to_level/1, open_logfile/2,
-        ensure_logfile/4, format_time/0, format_time/1]).
+        ensure_logfile/4, format_time/0, format_time/1, localtime_ms/0, maybe_utc/1]).
 
 levels() ->
     [debug, info, notice, warning, error, critical, alert, emergency].
@@ -95,10 +95,28 @@ ensure_logfile(Name, FD, Inode, Buffer) ->
             end
     end.
 
+%% returns localtime with milliseconds included
+localtime_ms() ->
+    {_, _, Micro} = Now = os:timestamp(),
+    {Date, {Hours, Minutes, Seconds}} = calendar:now_to_local_time(Now),
+    {Date, {Hours, Minutes, Seconds, Micro div 1000 rem 1000}}.
+
+maybe_utc({Date, {H, M, S, Ms}}) ->
+    case lager_stdlib:maybe_utc({Date, {H, M, S}}) of
+        {utc, {Date1, {H1, M1, S1}}} ->
+            {utc, {Date1, {H1, M1, S1, Ms}}};
+        {Date1, {H1, M1, S1}} ->
+            {Date1, {H1, M1, S1, Ms}}
+    end.
+
 format_time() ->
-    format_time(lager_stdlib:maybe_utc(erlang:localtime())).
+    format_time(maybe_utc(localtime_ms())).
 
+format_time({utc, {{Y, M, D}, {H, Mi, S, Ms}}}) ->
+    {io_lib:format("~b-~2..0b-~2..0b", [Y, M, D]), io_lib:format("~2..0b:~2..0b:~2..0b.~3..0b UTC", [H, Mi, S, Ms])};
+format_time({{Y, M, D}, {H, Mi, S, Ms}}) ->
+    {io_lib:format("~b-~2..0b-~2..0b", [Y, M, D]), io_lib:format("~2..0b:~2..0b:~2..0b.~3..0b", [H, Mi, S, Ms])};
 format_time({utc, {{Y, M, D}, {H, Mi, S}}}) ->
-    io_lib:format("~b-~2..0b-~2..0b ~2..0b:~2..0b:~2..0b UTC", [Y, M, D, H, Mi, S]);
+    {io_lib:format("~b-~2..0b-~2..0b", [Y, M, D]), io_lib:format("~2..0b:~2..0b:~2..0b UTC", [H, Mi, S])};
 format_time({{Y, M, D}, {H, Mi, S}}) ->
-    io_lib:format("~b-~2..0b-~2..0b ~2..0b:~2..0b:~2..0b", [Y, M, D, H, Mi, S]).
+    {io_lib:format("~b-~2..0b-~2..0b", [Y, M, D]), io_lib:format("~2..0b:~2..0b:~2..0b", [H, Mi, S])}.

test/lager_test_backend.erl

@@ -82,7 +82,7 @@ count_ignored() ->
     gen_event:call(lager_event, ?MODULE, count_ignored).
 
 not_running_test() ->
-    ?assertEqual({error, lager_not_running}, lager:log(info, wtf, "not running")).
+    ?assertEqual({error, lager_not_running}, lager:log(info, self(), "not running")).
 
 lager_test_() ->
     {foreach,