diff --git a/README.md b/README.md index 181c2751..f78abd3f 100644 --- a/README.md +++ b/README.md @@ -139,7 +139,6 @@ My Application |--[STDOUT]--> logs ---> Timber ---> |-- new relic / etc [Mind-blown!](http://i.giphy.com/EldfH1VJdbrwY.gif) - ## The Timber Console / Pricing > This is all gravy, but wouldn't the extra data get expensive? 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..fcc50566 100644 --- a/lib/timber/log_devices/http.rb +++ b/lib/timber/log_devices/http.rb @@ -1,19 +1,17 @@ -require "monitor" -require "msgpack" +require "timber/log_devices/http/triggered_buffer" 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 over HTTPS to the Timber API in batches. + # The buffer and delivery strategy are very efficient and the log messages will be delivered in + # msgpack format. + # + # See {#initialize} for options and more details. class HTTP - class DeliveryError < StandardError; 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 @@ -23,60 +21,100 @@ class DeliveryError < StandardError; end end https.open_timeout = 10 end + DELIVERY_FREQUENCY_SECONDS = 2.freeze + RETRY_LIMIT = 3.freeze + BACKOFF_RATE_SECONDS = 3.freeze - DEFAULT_DELIVERY_FREQUENCY = 2.freeze - # Instantiates a new HTTP log device. + # Instantiates a new HTTP log device that can be passed to {Timber::Logger#initialize}. # # @param api_key [String] The API key provided to you after you add your application to # [Timber](https://timber.io). # @param [Hash] options the options to create a HTTP log device with. - # @option attributes [Symbol] :frequency_seconds (2) How often the client should + # @option attributes [Symbol] :payload_limit_bytes Determines the maximum size in bytes that + # and HTTP payload can be. Please see {TriggereBuffer#initialize} for the default. + # @option attributes [Symbol] :buffer_limit_bytes Determines the maximum size of the total + # buffer. This should be many times larger than the `:payload_limit_bytes`. + # Please see {TriggereBuffer#initialize} for the default. + # @option attributes [Symbol] :buffer_overflow_handler (nil) When a single message exceeds + # `:payload_limit_bytes` or the entire buffer exceeds `:buffer_limit_bytes`, the Proc + # passed to this option will be called with the msg that would overflow the buffer. See + # the examples on how to use this properly. + # @option attributes [Symbol] :delivery_frequency_seconds (2) How often the client should # attempt to deliver logs to the Timber API. The HTTP client buffers logs between calls. + # + # @example Basic usage + # Timber::Logger.new(Timber::LogDevices::HTTP.new("my_timber_api_key")) + # + # @example Handling buffer overflows + # # Persist overflowed lines to a file + # # Note: You could write these to any permanent storage. + # overflow_log_path = "/path/to/my/overflow_log.log" + # overflow_handler = Proc.new { |log_line_msg| File.write(overflow_log_path, log_line_ms) } + # http_log_device = Timber::LogDevices::HTTP.new("my_timber_api_key", + # buffer_overflow_handler: overflow_handler) + # Timber::Logger.new(http_log_device) 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[:delivery_frequency_seconds] || DELIVERY_FREQUENCY_SECONDS) + buffer_for_delivery = @buffer.reserve + if buffer_for_delivery + deliver(buffer_for_delivery) + end end end end + # Write a new log line message to the buffer, and deliver if the msg exceeds the + # payload limit. def write(msg) - @monitor.synchronize { - @buffer << msg - } + buffer_for_delivery = @buffer.write(msg) + if buffer_for_delivery + deliver(buffer_for_delivery) + end + true end + # Closes the log device, cleans up, and attempts one last delivery. 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 + def deliver(body) + Thread.new do + RETRY_LIMIT.times do |try_index| + 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 - 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}") + res = HTTPS.request(request) + code = res.code.to_i + if code < 200 || code >= 300 + Config.instance.logger.debug("Timber HTTP delivery failed - #{res.code}: #{res.body}") + sleep((try_index + 1) * BACKOFF_RATE_SECONDS) + else + @buffer.remove(body) + Config.instance.logger.debug("Timber HTTP delivery successful - #{code}") + break # exit the loop + end end - Config.instance.logger.debug("Success! #{code}: #{res.body}") end - - @buffer.clear end def authorization_payload diff --git a/lib/timber/log_devices/http/triggered_buffer.rb b/lib/timber/log_devices/http/triggered_buffer.rb new file mode 100644 index 00000000..c08ee6e5 --- /dev/null +++ b/lib/timber/log_devices/http/triggered_buffer.rb @@ -0,0 +1,79 @@ +require "monitor" + +module Timber + module LogDevices + class HTTP + # 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.nil? || 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 + + def remove(buffer) + @monitor.synchronize do + @buffers.delete(buffer) + 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 + end + end +end \ No newline at end of file diff --git a/lib/timber/logger.rb b/lib/timber/logger.rb index 511730b8..cdd4f20a 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 @@ -127,7 +143,20 @@ def call(severity, time, progname, msg) # logger.formatter = Timber::Logger::JSONFormatter.new def initialize(*args) super(*args) - self.formatter = HybridFormatter.new + if args.size == 1 and args.first.is_a?(LogDevices::HTTP) + self.formatter = MsgPackFormatter.new + else + self.formatter = HybridFormatter.new + end + end + + def formatter=(value) + if @dev.is_a?(Timber::LogDevices::HTTP) + raise ArgumentError.new("The formatter cannot be changed when using the " + + "Timber::LogDevices::HTTP log device. The MsgPackFormatter must be used for proper " + + "delivery.") + end + super end # Backwards compatibility with older ActiveSupport::Logger versions diff --git a/spec/timber/log_devices/http/triggered_buffer_spec.rb b/spec/timber/log_devices/http/triggered_buffer_spec.rb new file mode 100644 index 00000000..4635eb48 --- /dev/null +++ b/spec/timber/log_devices/http/triggered_buffer_spec.rb @@ -0,0 +1,58 @@ +require "spec_helper" + +describe Timber::LogDevices::HTTP::TriggeredBuffer do + describe "#write" do + it "should trigger a buffer overflow for large messages" do + buffer = described_class.new(:payload_limit_bytes => 10) + msg = "a" * 11 + expect(buffer).to receive(:handle_overflow).exactly(1).times.with(msg) + buffer.write(msg) + end + + it "should trigger a buffer overflow when exceeding the limit" do + buffer = described_class.new(:limit_bytes => 10) + msg = "a" * 11 + expect(buffer).to receive(:handle_overflow).exactly(1).times.with(msg) + buffer.write(msg) + end + + it "should start a new buffer when empty and append when not" do + buffer = described_class.new + result = buffer.write("test") + expect(result).to be_nil + expect(buffer.send(:writable_buffer)).to eq("test") + result = buffer.write("again") + expect(result).to be_nil + expect(buffer.send(:writable_buffer)).to eq("testagain") + end + + it "should return the old buffer when it has exceeded it's limit" do + buffer = described_class.new(:payload_limit_bytes => 10) + msg = "a" * 6 + result = buffer.write(msg) + expect(result).to be_nil + result = buffer.write(msg) + expect(result).to eq(msg) + expect(result).to be_frozen + end + + it "should write a new buffer when the latest is frozen" do + buffer = described_class.new + buffer.write("test") + result = buffer.reserve + expect(result).to eq("test") + buffer.write("again") + expect(buffer.send(:writable_buffer)).to eq("again") + end + end + + describe "#reserve" do + it "should reserve the latest buffer and freeze it" do + buffer = described_class.new + buffer.write("test") + result = buffer.reserve + expect(result).to eq("test") + expect(result).to be_frozen + end + end +end \ No newline at end of file diff --git a/spec/timber/log_devices/http_spec.rb b/spec/timber/log_devices/http_spec.rb index b4f48b1b..edd7661b 100644 --- a/spec/timber/log_devices/http_spec.rb +++ b/spec/timber/log_devices/http_spec.rb @@ -1,62 +1,85 @@ -# 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 + 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", delivery_frequency_seconds: 0.1) + thread = http.instance_variable_get(:@delivery_interval_thread) + expect(thread).to be_alive + + http.write("my log message") + sleep 0.3 # 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") } + + after(:each) { http.close } + + it "should delivery properly and flush the buffer" do + 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/x-timber-msgpack-frame-1', + 'User-Agent' => "Timber Ruby Gem/#{Timber::VERSION}" + } + ). + to_return(:status => 200, :body => "", :headers => {}) + + http.write("test log message") + buffer = http.instance_variable_get(:@buffer) + buffers = buffer.instance_variable_get(:@buffers) + expect(buffers.size).to eq(1) + body = buffer.reserve + thread = http.send(:deliver, body) + thread.join + + expect(stub).to have_been_requested.times(1) + expect(buffers.size).to eq(0) + end + end +end \ No newline at end of file diff --git a/spec/timber/logger_spec.rb b/spec/timber/logger_spec.rb index a16177c9..2d2d2fad 100644 --- a/spec/timber/logger_spec.rb +++ b/spec/timber/logger_spec.rb @@ -75,5 +75,13 @@ expect(io.string).to eq("{\"level\":\"info\",\"dt\":\"2016-09-01T12:00:00.000000Z\",\"message\":\"this is a test\"}\n") end end + + context "with the HTTP log device" do + let(:io) { Timber::LogDevices::HTTP.new("my_key") } + + it "should use the msgpack formatter" do + expect(logger.formatter).to be_kind_of(Timber::Logger::MsgPackFormatter) + end + end end end \ No newline at end of file diff --git a/timberio.gemspec b/timberio.gemspec index aef17685..59ed80c5 100644 --- a/timberio.gemspec +++ b/timberio.gemspec @@ -8,8 +8,8 @@ Gem::Specification.new do |s| s.platform = Gem::Platform::RUBY s.authors = ["Timber Technologies, Inc."] s.email = ["hi@timber.io"] - s.homepage = "http://timber.io" - s.summary = "Logs you'll actually use." + s.homepage = "https://github.com/timberio/timber-ruby" + s.summary = "Instant log gratification." s.required_ruby_version = '>= 1.9.0'