diff --git a/lib/timber.rb b/lib/timber.rb index 3e1cb61b..eda8b628 100644 --- a/lib/timber.rb +++ b/lib/timber.rb @@ -1,5 +1,6 @@ # core classes require "json" # brings to_json to the core classes +require "msgpack" # brings to_msgpack to the core classes # Base (must come first, order matters) require "timber/config" diff --git a/lib/timber/log_devices/http.rb b/lib/timber/log_devices/http.rb index 34b2351d..5fc43f00 100644 --- a/lib/timber/log_devices/http.rb +++ b/lib/timber/log_devices/http.rb @@ -3,17 +3,88 @@ module Timber module LogDevices - # A log device that buffers and sends logs to the Timber API over HTTP in intervals. The buffer - # uses MessagePack::Buffer, which is fast, efficient with memory, and reduces - # the payload size sent to Timber. + # A log device that buffers and delivers log messages to the Timber API in batches. + # The payload is an array of msgpack formatter message delimited by new lines. Msgpack + # is an efficient way to represent JSON objects that save on space. + # + # Delivery has 2 triggers: a payload limit and a frequency, both defined by + # {PAYLOAD_LIMIT_BYTES} and {DELIVERY_FREQUENCY_SECONDS} respectively. If either are + # surpassed, a delivery will be attempted. + # + # In the event that the HTTP requests cannot empty the buffer fast enough, a buffer overflow + # will be triggered. This can be handled with the `:buffer_overflow_handler` option upon + # instantiation, allowing you to write the data to disk, etc. See {#new} for more details. class HTTP - class DeliveryError < StandardError; end + # Maintains a triggered buffer, where the trigger is {PAYLOAD_LIMIT_BYTES}. Once the buffer + # exceeds this limit it will lock and return that buffer up to that point while still making + # a new buffer available for writes. This ensures that the HTTP client can attempt to deliver + # the buffer contents without blocking execution of the application. + # + # If the overall buffer exceeeds the overall limit (specified by the `:limit_bytes` option), + # then a buffer overflow is triggered. This can be customized using the `:overflow_handler` + # option. + class TriggeredBuffer + DEFAULT_PAYLOAD_LIMIT_BYTES = 5_000_000 # 5mb, the Timber API will not accept messages larger than this + DEFAULT_LIMIT_BYTES = 50_000_000 # 50mb + + def initialize(options = {}) + @buffers = [] + @monitor = Monitor.new + @payload_limit_bytes = options[:payload_limit_bytes] || DEFAULT_PAYLOAD_LIMIT_BYTES + @limit_bytes = options[:limit_bytes] || DEFAULT_LIMIT_BYTES + @overflow_handler = options[:overflow_handler] + end + + def write(msg) + if msg.bytesize > @payload_limit_bytes || (msg.bytesize + total_bytesize) > @limit_bytes + handle_overflow(msg) + return nil + end + + @monitor.synchronize do + buffer = writable_buffer + if @buffers == [] || buffer.frozen? + @buffers << msg + nil + elsif (buffer.bytesize + msg.bytesize) > @payload_limit_bytes + @buffers << msg + buffer.freeze + else + buffer << msg + nil + end + end + end + + def reserve + @monitor.synchronize do + buffer = writable_buffer + if buffer + buffer.freeze + end + end + end + + private + def total_bytesize + @buffers.reduce(0) { |acc, buffer| acc + buffer.bytesize } + end + + def writable_buffer + @buffers.find { |buffer| !buffer.frozen? } + end + + def handle_overflow(msg) + if @overflow_handler + @overflow_handler.call(msg) + end + end + end API_URI = URI.parse("https://api.timber.io/http_frames") - CONTENT_TYPE = "application/json".freeze + CONTENT_TYPE = "application/x-timber-msgpack-frame-1".freeze CONNECTION_HEADER = "keep-alive".freeze USER_AGENT = "Timber Ruby Gem/#{Timber::VERSION}".freeze - HTTPS = Net::HTTP.new(API_URI.host, API_URI.port).tap do |https| https.use_ssl = true https.read_timeout = 30 @@ -24,7 +95,10 @@ class DeliveryError < StandardError; end https.open_timeout = 10 end - DEFAULT_DELIVERY_FREQUENCY = 2.freeze + PAYLOAD_LIMIT_BYTES = 5_000_000 # 5mb + BUFFER_LIMIT_BYTES = 50_000_000 # 50mb + DELIVERY_FREQUENCY_SECONDS = 2.freeze + # Instantiates a new HTTP log device. # @@ -35,48 +109,58 @@ class DeliveryError < StandardError; end # attempt to deliver logs to the Timber API. The HTTP client buffers logs between calls. def initialize(api_key, options = {}) @api_key = api_key - @buffer = [] - @monitor = Monitor.new - @delivery_thread = Thread.new do - at_exit { deliver } + @buffer = TriggeredBuffer.new( + payload_limit_bytes: options[:payload_limit_bytes], + limit_bytes: options[:buffer_limit_bytes], + overflow_handler: options[:buffer_overflow_handler] + ) + @delivery_interval_thread = Thread.new do loop do - sleep options[:frequency_seconds] || DEFAULT_DELIVERY_FREQUENCY - deliver + sleep options[:frequency_seconds] || DELIVERY_FREQUENCY_SECONDS + buffer_for_delivery = @buffer.reserve + if buffer_for_delivery + deliver(buffer_for_delivery) + end end end end def write(msg) - @monitor.synchronize { - @buffer << msg - } + buffer_for_delivery = @buffer.write(msg) + if buffer_for_delivery + deliver(buffer_for_delivery) + end + true end def close - @delivery_thread.kill + @delivery_interval_thread.kill + buffer_for_delivery = @buffer.reserve + if buffer_for_delivery + deliver(buffer_for_delivery) + end end private - def deliver - body = @buffer.read - - request = Net::HTTP::Post.new(API_URI.request_uri).tap do |req| - req['Authorization'] = authorization_payload - req['Connection'] = CONNECTION_HEADER - req['Content-Type'] = CONTENT_TYPE - req['User-Agent'] = USER_AGENT - req.body = body - end - - HTTPS.request(request).tap do |res| - code = res.code.to_i - if code < 200 || code >= 300 - raise DeliveryError.new("Bad response from Timber API - #{res.code}: #{res.body}") + def deliver(body) + Thread.new do + request = Net::HTTP::Post.new(API_URI.request_uri).tap do |req| + req['Authorization'] = authorization_payload + req['Connection'] = CONNECTION_HEADER + req['Content-Type'] = CONTENT_TYPE + req['User-Agent'] = USER_AGENT + req.body = body end - Config.instance.logger.debug("Success! #{code}: #{res.body}") - end - @buffer.clear + HTTPS.request(request) + # HTTPS.request(request).tap do |res| + # code = res.code.to_i + # if code < 200 || code >= 300 + # raise DeliveryError.new("Bad response from Timber API - #{res.code}: #{res.body}") + # end + # Config.instance.logger.debug("Success! #{code}: #{res.body}") + # end + end end def authorization_payload diff --git a/lib/timber/logger.rb b/lib/timber/logger.rb index 511730b8..55470f5d 100644 --- a/lib/timber/logger.rb +++ b/lib/timber/logger.rb @@ -81,6 +81,27 @@ def build_log_entry(severity, time, progname, msg) end end + # Structures your log messages into Timber's hybrid format, which makes + # it easy to read while also appending the appropriate metadata. + # + # logger = Timber::Logger.new(STDOUT) + # logger.formatter = Timber::JSONFormatter.new + # + # Example message: + # + # My log message @timber.io {"level":"info","dt":"2016-09-01T07:00:00.000000-05:00"} + # + class HybridFormatter < Formatter + METADATA_CALLOUT = "@timber.io".freeze + + def call(severity, time, progname, msg) + log_entry = build_log_entry(severity, time, progname, msg) + metadata = log_entry.to_json(:except => [:message]) + # use << for concatenation for performance reasons + log_entry.message.gsub("\n", "\\n") << " " << METADATA_CALLOUT << " " << metadata << "\n" + end + end + # Structures your log messages into JSON. # # logger = Timber::Logger.new(STDOUT) @@ -97,24 +118,19 @@ def call(severity, time, progname, msg) end end - # Structures your log messages into Timber's hybrid format, which makes - # it easy to read while also appending the appropriate metadata. + # Structures your log messages into JSON. # # logger = Timber::Logger.new(STDOUT) # logger.formatter = Timber::JSONFormatter.new # # Example message: # - # My log message @timber.io {"level":"info","dt":"2016-09-01T07:00:00.000000-05:00"} + # {"level":"info","dt":"2016-09-01T07:00:00.000000-05:00","message":"My log message"} # - class HybridFormatter < Formatter - METADATA_CALLOUT = "@timber.io".freeze - + class MsgPackFormatter < Formatter def call(severity, time, progname, msg) - log_entry = build_log_entry(severity, time, progname, msg) - metadata = log_entry.to_json(:except => [:message]) # use << for concatenation for performance reasons - log_entry.message.gsub("\n", "\\n") << " " << METADATA_CALLOUT << " " << metadata << "\n" + build_log_entry(severity, time, progname, msg).as_json.to_msgpack << "\n" end end diff --git a/spec/timber/log_devices/http_spec.rb b/spec/timber/log_devices/http_spec.rb index b4f48b1b..567ebe93 100644 --- a/spec/timber/log_devices/http_spec.rb +++ b/spec/timber/log_devices/http_spec.rb @@ -1,62 +1,89 @@ -# require "spec_helper" - -# describe Timber::LogDevices::HTTP do -# # We have to define our own at_exit method, because the mocks and -# # everything are stripped out before. Otherwise it tries to issue -# # a request :( -# before(:each) do -# described_class.class_eval do -# def at_exit; true; end -# end -# end - -# describe "#initialize" do -# it "should start a thread for delivery" do -# allow_any_instance_of(described_class).to receive(:at_exit).exactly(1).times.and_return(true) -# expect_any_instance_of(described_class).to receive(:deliver).exactly(2).times.and_return(true) -# http = described_class.new("MYKEY", frequency_seconds: 0.1) -# thread = http.instance_variable_get(:@delivery_thread) -# expect(thread).to be_alive -# sleep 0.25 # allow 2 iterations -# http.close -# end -# end - -# describe "#write" do -# let(:http) { described_class.new("MYKEY") } -# let(:buffer) { http.instance_variable_get(:@buffer) } - -# after(:each) { http.close } - -# it "should buffer the messages" do -# http.write("test log message") -# expect(buffer.read).to eq("test log message") -# end -# end - -# describe "#deliver" do -# let(:http) { described_class.new("MYKEY") } -# let(:buffer) { http.instance_variable_get(:@buffer) } - -# after(:each) { http.close } - -# it "should delivery properly and flush the buffer" do -# expect_any_instance_of(described_class).to receive(:at_exit).exactly(1).times.and_return(true) -# stub = stub_request(:post, "https://api.timber.io/http_frames"). -# with( -# :body => "test log message", -# :headers => {'Authorization'=>'Basic TVlLRVk=', 'Connection'=>'keep-alive', 'Content-Type'=>'application/json', 'User-Agent'=>'Timber Ruby Gem/1.0.0'} -# ). -# to_return(:status => 200, :body => "", :headers => {}) - -# http.write("test log message") - -# expect(buffer).to_not be_empty - -# http.send(:deliver) - -# expect(stub).to have_been_requested.times(1) -# expect(buffer).to be_empty -# end -# end -# end \ No newline at end of file +require "spec_helper" + +describe Timber::LogDevices::HTTP do + # We have to define our own at_exit method, because the mocks and + # everything are stripped out before. Otherwise it tries to issue + # a request :( + before(:each) do + described_class.class_eval do + def at_exit; true; end + end + end + + describe "#initialize" do + it "should start a thread for delivery" do + expect_any_instance_of(described_class).to receive(:deliver).at_least(1).times.and_return(true) + http = described_class.new("MYKEY", frequency_seconds: 0.1) + thread = http.instance_variable_get(:@delivery_interval_thread) + expect(thread).to be_alive + + http.write("my log message") + sleep 0.2 # too fast! + end + end + + describe "#write" do + let(:http) { described_class.new("MYKEY") } + let(:buffer) { http.instance_variable_get(:@buffer) } + + it "should buffer the messages" do + http.write("test log message") + expect(buffer.reserve).to eq("test log message") + end + + context "with a low payload limit" do + let(:http) { described_class.new("MYKEY", :payload_limit_bytes => 20) } + + it "should attempt a delivery when the payload limit is exceeded" do + message = "a" * 19 + http.write(message) + expect(http).to receive(:deliver).exactly(1).times.with(message) + http.write("my log message") + end + end + end + + describe "#close" do + let(:http) { described_class.new("MYKEY") } + + it "should kill the delivery thread the messages" do + http.close + thread = http.instance_variable_get(:@delivery_interval_thread) + sleep 0.1 # too fast! + expect(thread).to_not be_alive + end + + it "should attempt a delivery" do + message = "a" * 19 + http.write(message) + expect(http).to receive(:deliver).exactly(1).times.with(message) + http.close + end + end + + # describe "#deliver" do + # let(:http) { described_class.new("MYKEY") } + # let(:buffer) { http.instance_variable_get(:@buffer) } + + # after(:each) { http.close } + + # it "should delivery properly and flush the buffer" do + # expect_any_instance_of(described_class).to receive(:at_exit).exactly(1).times.and_return(true) + # stub = stub_request(:post, "https://api.timber.io/http_frames"). + # with( + # :body => "test log message", + # :headers => {'Authorization'=>'Basic TVlLRVk=', 'Connection'=>'keep-alive', 'Content-Type'=>'application/json', 'User-Agent'=>'Timber Ruby Gem/1.0.0'} + # ). + # to_return(:status => 200, :body => "", :headers => {}) + + # http.write("test log message") + + # expect(buffer).to_not be_empty + + # http.send(:deliver) + + # expect(stub).to have_been_requested.times(1) + # expect(buffer).to be_empty + # end + # end +end \ No newline at end of file