| %% Copyright (c) 2011 Basho Technologies, Inc. All Rights Reserved. |
| %% |
| %% 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. |
| |
| %% @doc File backend for lager, with multiple file support. |
| %% Multiple files are supported, each with the path and the loglevel being |
| %% configurable. The configuration paramter for this backend is a list of |
| %% 5-tuples of the form |
| %% `{FileName, Level, RotationSize, RotationDate, RotationCount}'. |
| %% This backend supports external and internal log |
| %% rotation and will re-open handles to files if the inode changes. It will |
| %% also rotate the files itself if the size of the file exceeds the |
| %% `RotationSize' and keep `RotationCount' rotated files. `RotationDate' is |
| %% an alternate rotation trigger, based on time. See the README for |
| %% documentation. |
| |
| -module(lager_file_backend). |
| |
| -include("lager.hrl"). |
| |
| -behaviour(gen_event). |
| |
| -ifdef(TEST). |
| -include_lib("eunit/include/eunit.hrl"). |
| -include_lib("kernel/include/file.hrl"). |
| -endif. |
| |
| -export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2, |
| code_change/3]). |
| |
| -record(state, {files}). |
| |
| -record(file, { |
| name :: string(), |
| level :: integer(), |
| fd :: file:io_device(), |
| inode :: integer(), |
| flap=false :: boolean(), |
| size = 0 :: integer(), |
| date, |
| count = 10 |
| }). |
| |
| %% @private |
| -spec init([{string(), lager:log_level()},...]) -> {ok, #state{}}. |
| init(LogFiles) -> |
| Files = [begin |
| schedule_rotation(Name, Date), |
| case lager_util:open_logfile(Name, true) of |
| {ok, {FD, Inode, _}} -> |
| #file{name=Name, level=lager_util:level_to_num(Level), |
| fd=FD, inode=Inode, size=Size, date=Date, count=Count}; |
| {error, Reason} -> |
| ?INT_LOG(error, "Failed to open log file ~s with error ~s", |
| [Name, file:format_error(Reason)]), |
| #file{name=Name, level=lager_util:level_to_num(Level), |
| flap=true, size=Size, date=Date, count=Count} |
| end |
| end || |
| {Name, Level, Size, Date, Count} <- validate_logfiles(LogFiles)], |
| {ok, #state{files=Files}}. |
| |
| %% @private |
| handle_call({set_loglevel, _}, State) -> |
| {ok, {error, missing_identifier}, State}; |
| handle_call({set_loglevel, Ident, Level}, #state{files=Files} = State) -> |
| case lists:keyfind(Ident, 2, Files) of |
| false -> |
| %% no such file exists |
| {ok, {error, bad_identifier}, State}; |
| _ -> |
| NewFiles = lists:map( |
| fun(#file{name=Name} = File) when Name == Ident -> |
| ?INT_LOG(notice, "Changed loglevel of ~s to ~p", |
| [Ident, Level]), |
| File#file{level=lager_util:level_to_num(Level)}; |
| (X) -> X |
| end, Files), |
| {ok, ok, State#state{files=NewFiles}} |
| end; |
| handle_call(get_loglevel, #state{files=Files} = State) -> |
| Result = lists:foldl(fun(#file{level=Level}, L) -> erlang:max(Level, L); |
| (_, L) -> L end, -1, |
| Files), |
| {ok, Result, State}; |
| handle_call(_Request, State) -> |
| {ok, ok, State}. |
| |
| %% @private |
| 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, [Date, " ", Time, " ", Message, "\n"]); |
| (File) -> |
| File |
| end, Files), |
| {ok, State#state{files=NewFiles}}; |
| handle_event(_Event, State) -> |
| {ok, State}. |
| |
| %% @private |
| handle_info({rotate, File}, #state{files=Files} = State) -> |
| case lists:keyfind(File, #file.name, Files) of |
| false -> |
| %% no such file exists |
| ?INT_LOG(warning, "Asked to rotate non-existant file ~p", [File]), |
| {ok, State}; |
| #file{name=Name, date=Date, count=Count} -> |
| lager_util:rotate_logfile(Name, Count), |
| schedule_rotation(Name, Date), |
| {ok, State} |
| end; |
| handle_info(_Info, State) -> |
| {ok, State}. |
| |
| %% @private |
| terminate(_Reason, State) -> |
| %% flush and close any file handles |
| lists:foreach( |
| fun({_, _, FD, _}) -> file:datasync(FD), file:close(FD); |
| (_) -> ok |
| end, State#state.files). |
| |
| %% @private |
| code_change(_OldVsn, State, _Extra) -> |
| {ok, State}. |
| |
| write(#file{name=Name, fd=FD, inode=Inode, flap=Flap, size=RotSize, |
| count=Count} = File, Level, Msg) -> |
| case lager_util:ensure_logfile(Name, FD, Inode, true) of |
| {ok, {_, _, Size}} when RotSize /= 0, Size > RotSize -> |
| lager_util:rotate_logfile(Name, Count), |
| write(File, Level, Msg); |
| {ok, {NewFD, NewInode, _}} -> |
| file:write(NewFD, Msg), |
| case Level of |
| _ when Level =< ?ERROR -> |
| %% force a sync on any message at error severity or above |
| Flap2 = case file:datasync(NewFD) of |
| {error, Reason2} when Flap == false -> |
| ?INT_LOG(error, "Failed to write log message to file ~s: ~s", |
| [Name, file:format_error(Reason2)]), |
| true; |
| ok -> |
| false; |
| _ -> |
| Flap |
| end, |
| File#file{fd=NewFD, inode=NewInode, flap=Flap2}; |
| _ -> |
| File#file{fd=NewFD, inode=NewInode} |
| end; |
| {error, Reason} -> |
| case Flap of |
| true -> |
| File; |
| _ -> |
| ?INT_LOG(error, "Failed to reopen log file ~s with error ~s", |
| [Name, file:format_error(Reason)]), |
| File#file{flap=true} |
| end |
| end. |
| |
| validate_logfiles([]) -> |
| []; |
| validate_logfiles([{Name, Level}|T]) -> |
| case lists:member(Level, ?LEVELS) of |
| true -> |
| [{Name, Level, 0, undefined, 0}|validate_logfiles(T)]; |
| _ -> |
| ?INT_LOG(error, "Invalid log level of ~p for ~s.", |
| [Level, Name]), |
| validate_logfiles(T) |
| end; |
| validate_logfiles([{Name, Level, Size, Date, Count}|T]) -> |
| ValidLevel = (lists:member(Level, ?LEVELS)), |
| ValidSize = (is_integer(Size) andalso Size >= 0), |
| ValidCount = (is_integer(Count) andalso Count >= 0), |
| case {ValidLevel, ValidSize, ValidCount} of |
| {false, _, _} -> |
| ?INT_LOG(error, "Invalid log level of ~p for ~s.", |
| [Level, Name]), |
| validate_logfiles(T); |
| {_, false, _} -> |
| ?INT_LOG(error, "Invalid rotation size of ~p for ~s.", |
| [Size, Name]), |
| validate_logfiles(T); |
| {_, _, false} -> |
| ?INT_LOG(error, "Invalid rotation count of ~p for ~s.", |
| [Count, Name]), |
| validate_logfiles(T); |
| {true, true, true} -> |
| case lager_util:parse_rotation_date_spec(Date) of |
| {ok, Spec} -> |
| [{Name, Level, Size, Spec, |
| Count}|validate_logfiles(T)]; |
| {error, _} when Date == "" -> |
| %% blank ones are fine. |
| [{Name, Level, Size, undefined, |
| Count}|validate_logfiles(T)]; |
| {error, _} -> |
| ?INT_LOG(error, "Invalid rotation date of ~p for ~s.", |
| [Date, Name]), |
| validate_logfiles(T) |
| end |
| end; |
| validate_logfiles([H|T]) -> |
| ?INT_LOG(error, "Invalid log file config ~p.", [H]), |
| validate_logfiles(T). |
| |
| schedule_rotation(_, undefined) -> |
| undefined; |
| schedule_rotation(Name, Date) -> |
| erlang:send_after(lager_util:calculate_next_rotation(Date) * 1000, self(), {rotate, Name}). |
| |
| -ifdef(TEST). |
| |
| get_loglevel_test() -> |
| {ok, Level, _} = handle_call(get_loglevel, |
| #state{files=[ |
| #file{name="foo", level=lager_util:level_to_num(warning), fd=0, inode=0}, |
| #file{name="bar", level=lager_util:level_to_num(info), fd=0, inode=0}]}), |
| ?assertEqual(Level, lager_util:level_to_num(info)), |
| {ok, Level2, _} = handle_call(get_loglevel, |
| #state{files=[ |
| #file{name="foo", level=lager_util:level_to_num(warning), fd=0, inode=0}, |
| #file{name="foo", level=lager_util:level_to_num(critical), fd=0, inode=0}, |
| #file{name="bar", level=lager_util:level_to_num(error), fd=0, inode=0}]}), |
| ?assertEqual(Level2, lager_util:level_to_num(warning)). |
| |
| rotation_test() -> |
| {ok, {FD, Inode, _}} = lager_util:open_logfile("test.log", true), |
| ?assertMatch(#file{name="test.log", level=?DEBUG, fd=FD, inode=Inode}, |
| write(#file{name="test.log", level=?DEBUG, fd=FD, inode=Inode}, 0, "hello world")), |
| file:delete("test.log"), |
| Result = write(#file{name="test.log", level=?DEBUG, fd=FD, inode=Inode}, 0, "hello world"), |
| %% assert file has changed |
| ?assert(#file{name="test.log", level=?DEBUG, fd=FD, inode=Inode} =/= Result), |
| ?assertMatch(#file{name="test.log", level=?DEBUG}, Result), |
| file:rename("test.log", "test.log.1"), |
| Result2 = write(Result, 0, "hello world"), |
| %% assert file has changed |
| ?assert(Result =/= Result2), |
| ?assertMatch(#file{name="test.log", level=?DEBUG}, Result2), |
| ok. |
| |
| filesystem_test_() -> |
| {foreach, |
| fun() -> |
| file:write_file("test.log", ""), |
| error_logger:tty(false), |
| application:load(lager), |
| application:set_env(lager, handlers, [{lager_test_backend, info}]), |
| application:set_env(lager, error_logger_redirect, false), |
| application:start(lager) |
| end, |
| fun(_) -> |
| file:delete("test.log"), |
| application:stop(lager), |
| error_logger:tty(true) |
| end, |
| [ |
| {"under normal circumstances, file should be opened", |
| fun() -> |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| lager:log(error, self(), "Test message"), |
| {ok, Bin} = file:read_file("test.log"), |
| Pid = pid_to_list(self()), |
| ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) |
| end |
| }, |
| {"file can't be opened on startup triggers an error message", |
| fun() -> |
| {ok, FInfo} = file:read_file_info("test.log"), |
| file:write_file_info("test.log", FInfo#file_info{mode = 0}), |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual(1, lager_test_backend:count()), |
| {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), |
| ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)) |
| end |
| }, |
| {"file that becomes unavailable at runtime should trigger an error message", |
| fun() -> |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual(0, lager_test_backend:count()), |
| lager:log(error, self(), "Test message"), |
| ?assertEqual(1, lager_test_backend:count()), |
| file:delete("test.log"), |
| file:write_file("test.log", ""), |
| {ok, FInfo} = file:read_file_info("test.log"), |
| file:write_file_info("test.log", FInfo#file_info{mode = 0}), |
| lager:log(error, self(), "Test message"), |
| ?assertEqual(3, lager_test_backend:count()), |
| lager_test_backend:pop(), |
| lager_test_backend:pop(), |
| {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), |
| ?assertEqual("Failed to reopen log file test.log with error permission denied", lists:flatten(Message)) |
| end |
| }, |
| {"unavailable files that are fixed at runtime should start having log messages written", |
| fun() -> |
| {ok, FInfo} = file:read_file_info("test.log"), |
| OldPerms = FInfo#file_info.mode, |
| file:write_file_info("test.log", FInfo#file_info{mode = 0}), |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual(1, lager_test_backend:count()), |
| {_Level, _Time, [_, _, Message]} = lager_test_backend:pop(), |
| ?assertEqual("Failed to open log file test.log with error permission denied", lists:flatten(Message)), |
| file:write_file_info("test.log", FInfo#file_info{mode = OldPerms}), |
| lager:log(error, self(), "Test message"), |
| {ok, Bin} = file:read_file("test.log"), |
| Pid = pid_to_list(self()), |
| ?assertMatch([_, _, "[error]", Pid, "Test message\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])) |
| end |
| }, |
| {"external logfile rotation/deletion should be handled", |
| fun() -> |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual(0, lager_test_backend:count()), |
| lager:log(error, self(), "Test message1"), |
| ?assertEqual(1, lager_test_backend:count()), |
| file:delete("test.log"), |
| file:write_file("test.log", ""), |
| lager:log(error, self(), "Test message2"), |
| {ok, Bin} = file:read_file("test.log"), |
| Pid = pid_to_list(self()), |
| ?assertMatch([_, _, "[error]", Pid, "Test message2\n"], re:split(Bin, " ", [{return, list}, {parts, 5}])), |
| file:rename("test.log", "test.log.0"), |
| lager:log(error, self(), "Test message3"), |
| {ok, Bin2} = file:read_file("test.log"), |
| ?assertMatch([_, _, "[error]", Pid, "Test message3\n"], re:split(Bin2, " ", [{return, list}, {parts, 5}])) |
| end |
| }, |
| {"runtime level changes", |
| fun() -> |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual(0, lager_test_backend:count()), |
| lager:log(info, self(), "Test message1"), |
| lager:log(error, self(), "Test message2"), |
| {ok, Bin} = file:read_file("test.log"), |
| Lines = length(re:split(Bin, "\n", [{return, list}, trim])), |
| ?assertEqual(Lines, 2), |
| ?assertEqual(ok, lager:set_loglevel(lager_file_backend, "test.log", warning)), |
| lager:log(info, self(), "Test message3"), %% this won't get logged |
| lager:log(error, self(), "Test message4"), |
| {ok, Bin2} = file:read_file("test.log"), |
| Lines2 = length(re:split(Bin2, "\n", [{return, list}, trim])), |
| ?assertEqual(Lines2, 3) |
| end |
| }, |
| {"invalid runtime level changes", |
| fun() -> |
| gen_event:add_handler(lager_event, lager_file_backend, [{"test.log", info}]), |
| ?assertEqual({error, bad_identifier}, lager:set_loglevel(lager_file_backend, "test2.log", warning)), |
| ?assertEqual({error, missing_identifier}, lager:set_loglevel(lager_file_backend, warning)) |
| end |
| } |
| |
| ] |
| }. |
| |
| |
| -endif. |
| |
