require "spec_helper" describe Timber::Logger, :rails_23 => true do describe "#initialize" do it "shoud select the augmented formatter" do logger = described_class.new(nil) expect(logger.formatter).to be_kind_of(Timber::Logger::AugmentedFormatter) end context "development environment" do around(:each) do |example| old_env = Timber::Config.instance.environment Timber::Config.instance.environment = "development" example.run Timber::Config.instance.environment = old_env end it "shoud select the message only formatter" do logger = described_class.new(nil) expect(logger.formatter).to be_kind_of(Timber::Logger::MessageOnlyFormatter) end end it "should allow multiple loggers" do io1 = StringIO.new io2 = StringIO.new logger = Timber::Logger.new(STDOUT, io1, io2) logger.info("hello world") expect(io1.string).to start_with("hello world @metadata {") expect(io2.string).to start_with("hello world @metadata {") end end describe "#add" do let(:time) { Time.utc(2016, 9, 1, 12, 0, 0) } let(:io) { StringIO.new } let(:logger) { Timber::Logger.new(io) } around(:each) do |example| Timecop.freeze(time) { example.run } end it "should respect the level via Logger constants" do logger.formatter = Timber::Logger::MessageOnlyFormatter.new logger.level = ::Logger::DEBUG logger.info("message") expect(io.string).to eq("message\n") io.string = "" logger.level = ::Logger::WARN logger.info("message") expect(io.string).to eq("") end it "should respect the level via level symbols" do logger.formatter = Timber::Logger::MessageOnlyFormatter.new logger.level = :debug logger.info("message") expect(io.string).to eq("message\n") io.string = "" logger.level = :warn logger.info("message") expect(io.string).to eq("") end context "with the AugmentedFormatter" do before(:each) { logger.formatter = Timber::Logger::AugmentedFormatter.new } it "should accept strings" do logger.info("this is a test") expect(io.string).to start_with("this is a test @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") end it "should accept non-strings" do logger.info(true) expect(io.string).to start_with("true @metadata") end context "with a context" do let(:http_context) do Timber::Contexts::HTTP.new( method: "POST", path: "/checkout", remote_addr: "123.456.789.10", request_id: "abcd1234" ) end around(:each) do |example| Timber::CurrentContext.with(http_context) do example.run end end it "should snapshot and include the context" do expect(Timber::CurrentContext.instance).to receive(:snapshot).and_call_original logger.info("this is a test") expect(io.string).to start_with("this is a test @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\"") expect(io.string).to include("\"http\":{\"method\":\"POST\",\"path\":\"/checkout\",\"remote_addr\":\"123.456.789.10\",\"request_id\":\"abcd1234\"}") end end it "should call and use Timber::Events.build" do message = {message: "payment rejected", payment_rejected: {customer_id: "abcde1234", amount: 100}} expect(Timber::Events).to receive(:build).with(message).and_call_original logger.info(message) expect(io.string).to start_with("payment rejected @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"custom\":{\"payment_rejected\":{\"customer_id\":\"abcde1234\",\"amount\":100}}}") end it "should log properly when a Timber::Event object is passed" do message = Timber::Events::SQLQuery.new(sql: "select * from users", time_ms: 56, message: "select * from users") logger.info(message) expect(io.string).to start_with("select * from users @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"sql_query\":{\"sql\":\"select * from users\",\"time_ms\":56.0}}") end it "should allow :time_ms" do logger.info("event complete", time_ms: 54.5) expect(io.string).to include("\"time_ms\":54.5") end it "should allow :tag" do logger.info("event complete", tag: "tag1") expect(io.string).to include("\"tags\":[\"tag1\"]") end it "should allow :tags" do tags = ["tag1", "tag2"] logger.info("event complete", tags: tags) expect(io.string).to include("\"tags\":[\"tag1\",\"tag2\"]") # Ensure the tags object is not modified expect(tags).to eq(["tag1", "tag2"]) end it "should allow functions" do logger.info do {message: "payment rejected", payment_rejected: {customer_id: "abcde1234", amount: 100}} end expect(io.string).to start_with("payment rejected @metadata {\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",") expect(io.string).to include("\"event\":{\"custom\":{\"payment_rejected\":{\"customer_id\":\"abcde1234\",\"amount\":100}}}") end it "should escape new lines" do logger.info "first\nsecond" expect(io.string).to start_with("first\\nsecond @metadata") end end context "with the JSONFormatter" do before(:each) { logger.formatter = Timber::Logger::JSONFormatter.new } it "should log in the correct format" do logger.info("this is a test") expect(io.string).to start_with("{\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",\"message\":\"this is a test\"") end end context "with the HTTP log device" do let(:io) { Timber::LogDevices::HTTP.new("my_key") } it "should use the PassThroughFormatter" do expect(logger.formatter).to be_kind_of(Timber::Logger::PassThroughFormatter) end end end describe "#error" do let(:io) { StringIO.new } let(:logger) { Timber::Logger.new(io) } it "should allow default usage" do logger.error("message") expect(io.string).to start_with("message @metadata") expect(io.string).to include('"level":"error"') end it "should allow messages with options" do logger.error("message", tag: "tag") expect(io.string).to start_with("message @metadata") expect(io.string).to include('"level":"error"') expect(io.string).to include('"tags":["tag"]') end end describe "#formatter=" do it "should not allow changing the formatter when the device is HTTP" do http_device = Timber::LogDevices::HTTP.new("api_key") logger = Timber::Logger.new(http_device) expect { logger.formatter = ::Logger::Formatter.new }.to raise_error(ArgumentError) end it "should set the formatter" do logger = Timber::Logger.new(STDOUT) formatter = ::Logger::Formatter.new logger.formatter = formatter expect(logger.formatter).to eq(formatter) end end describe "#info" do let(:io) { StringIO.new } let(:logger) { Timber::Logger.new(io) } it "should allow default usage" do logger.info("message") expect(io.string).to start_with("message @metadata") expect(io.string).to include('"level":"info"') end it "should allow messages with options" do logger.info("message", tag: "tag") expect(io.string).to start_with("message @metadata") expect(io.string).to include('"level":"info"') expect(io.string).to include('"tags":["tag"]') end it "should accept non-string messages" do logger.info(true) expect(io.string).to start_with("true @metadata") end end describe "#silence" do let(:io) { StringIO.new } let(:logger) { Timber::Logger.new(io) } it "should silence the logs" do logger.silence do logger.info("test") end expect(io.string).to eq("") end end describe "#with_context" do let(:io) { StringIO.new } let(:logger) { Timber::Logger.new(io) } it "should add context" do expect(Timber::CurrentContext.instance.send(:hash)[:custom]).to be_nil logger.with_context(build: {version: "1.0.0"}) do expect(Timber::CurrentContext.instance.send(:hash)[:custom]).to eq({:build=>{:version=>"1.0.0"}}) logger.with_context({testing: {key: "value"}}) do expect(Timber::CurrentContext.instance.send(:hash)[:custom]).to eq({:build=>{:version=>"1.0.0"}, :testing=>{:key=>"value"}}) end expect(Timber::CurrentContext.instance.send(:hash)[:custom]).to eq({:build=>{:version=>"1.0.0"}}) end expect(Timber::CurrentContext.instance.send(:hash)[:custom]).to be_nil end end end