From f0dfea9d80437078fd0be889f0087095bd4f9933 Mon Sep 17 00:00:00 2001 From: Andrew Cholakian Date: Tue, 31 May 2016 16:11:12 -0500 Subject: [PATCH] Improve error handling in API / Rack App. Setting error handling conditions in sinatra dynamically is not possible. The values such as :show_exceptions get set, but have no effect. This is esp. important in testing where we want failures to raise exceptions. Otherwise, debugging is a matter of parsing instructable HTML responses containing the debug info. We do not want this behavior by default however, as doing so would mean a single API bug would take down a production app. This change adds a new agent setting (not CLI setting) 'http.environment' that is defaulted to 'production'. If set to 'test' exceptions get raised. This change also removes sinatra error handlers that previously did nothing, and injects custom rack middleware to properly log and handle errors. Fixes #5411 --- logstash-core/lib/logstash/agent.rb | 3 +- .../lib/logstash/api/modules/base.rb | 17 ++-- .../lib/logstash/api/modules/node.rb | 2 + logstash-core/lib/logstash/api/rack_app.rb | 78 +++++++++++++++- logstash-core/lib/logstash/api/service.rb | 2 +- logstash-core/lib/logstash/environment.rb | 1 + logstash-core/lib/logstash/webserver.rb | 9 +- logstash-core/spec/api/lib/rack_app_spec.rb | 88 +++++++++++++++++++ logstash-core/spec/api/spec_helper.rb | 9 +- 9 files changed, 188 insertions(+), 21 deletions(-) create mode 100644 logstash-core/spec/api/lib/rack_app_spec.rb diff --git a/logstash-core/lib/logstash/agent.rb b/logstash-core/lib/logstash/agent.rb index 0e356ec76..8bb3649e9 100644 --- a/logstash-core/lib/logstash/agent.rb +++ b/logstash-core/lib/logstash/agent.rb @@ -38,6 +38,7 @@ class LogStash::Agent @node_name = setting("node.name") @http_host = setting("http.host") @http_port = setting("http.port") + @http_environment = setting("http.environment") @config_loader = LogStash::Config::Loader.new(@logger) @reload_interval = setting("config.reload.interval") @@ -129,7 +130,7 @@ class LogStash::Agent private def start_webserver - options = {:http_host => @http_host, :http_port => @http_port } + options = {:http_host => @http_host, :http_port => @http_port, :http_environment => @http_environment } @webserver = LogStash::WebServer.new(@logger, options) Thread.new(@webserver) do |webserver| LogStash::Util.set_thread_name("Api Webserver") diff --git a/logstash-core/lib/logstash/api/modules/base.rb b/logstash-core/lib/logstash/api/modules/base.rb index 4f9855f6e..7a750d02f 100644 --- a/logstash-core/lib/logstash/api/modules/base.rb +++ b/logstash-core/lib/logstash/api/modules/base.rb @@ -7,15 +7,16 @@ module LogStash class Base < ::Sinatra::Base helpers AppHelpers + # These options never change + # Sinatra isn't good at letting you change internal settings at runtime + # which is a requirement. We always propagate errors up and catch them + # in a custom rack handler in the RackApp class set :environment, :production + set :raise_errors, true + set :show_exceptions, false attr_reader :factory - if settings.environment != :production - set :raise_errors, true - set :show_exceptions, :after_handler - end - include LogStash::Util::Loggable helpers AppHelpers @@ -31,12 +32,6 @@ module LogStash text = as == :string ? "" : {} respond_with(text, :as => as) end - - error do - e = env['sinatra.error'] - logger.error(e.message, :url => request.url, :ip => request.ip, :params => request.params, :class => e.class.name, :backtrace => e.backtrace) - end - end end end diff --git a/logstash-core/lib/logstash/api/modules/node.rb b/logstash-core/lib/logstash/api/modules/node.rb index 931b2152c..38ae44f7b 100644 --- a/logstash-core/lib/logstash/api/modules/node.rb +++ b/logstash-core/lib/logstash/api/modules/node.rb @@ -1,4 +1,6 @@ # encoding: utf-8 +require "logstash/api/modules/base" + module LogStash module Api module Modules diff --git a/logstash-core/lib/logstash/api/rack_app.rb b/logstash-core/lib/logstash/api/rack_app.rb index 5624d1c35..861e26d06 100644 --- a/logstash-core/lib/logstash/api/rack_app.rb +++ b/logstash-core/lib/logstash/api/rack_app.rb @@ -1,3 +1,5 @@ +require "sinatra" +require "rack" require "logstash/api/modules/base" require "logstash/api/modules/node" require "logstash/api/modules/node_stats" @@ -8,9 +10,83 @@ require "logstash/api/modules/stats" module LogStash module Api module RackApp - def self.app + # Cabin is not compatible with CommonLogger, and this gives us more control anyway + METADATA_FIELDS = [:request_method, :path_info, :query_string, :http_version, :http_accept].freeze + def self.log_metadata(status, env) + METADATA_FIELDS.reduce({:status => status}) do |acc, field| + acc[field] = env[field.to_s.upcase] + acc + end + end + + class ApiLogger + LOG_MESSAGE = "API HTTP Request".freeze + + def initialize(app, logger) + @app = app + @logger = logger + end + + def call(env) + res = @app.call(env) + status, headers, body = res + + if fatal_error?(status) + @logger.warn? && @logger.warn(LOG_MESSAGE, RackApp.log_metadata(status, env)) + else + @logger.info? && @logger.info(LOG_MESSAGE, RackApp.log_metadata(status, env)) + end + + res + end + + def fatal_error?(status) + status >= 500 && status < 600 + end + end + + class ApiErrorHandler + LOG_MESSAGE = "Internal API server error".freeze + + def initialize(app, logger) + @app = app + @logger = logger + end + + def call(env) + @app.call(env) + rescue => e + body = RackApp.log_metadata(500, env). + merge({ + :error => "Unexpected Internal Error", + :class => e.class.name, + :message => e.message, + :backtrace => e.backtrace + }) + + @logger.error(LOG_MESSAGE, body) + + [500, + {'Content-Type' => 'application/json'}, + [LogStash::Json.dump(body)] + ] + end + end + + def self.app(logger, environment) namespaces = rack_namespaces Rack::Builder.new do + # Custom logger object. Rack CommonLogger does not work with cabin + use ApiLogger, logger + + # In test env we want errors to propogate up the chain + # so we get easy to understand test failures. + # In production / dev we don't want a bad API endpoint + # to crash the process + if environment != "test" + use ApiErrorHandler, logger + end + run LogStash::Api::Modules::Root namespaces.each_pair do |namespace, app| map(namespace) do diff --git a/logstash-core/lib/logstash/api/service.rb b/logstash-core/lib/logstash/api/service.rb index 799e802b6..3eaeb2535 100644 --- a/logstash-core/lib/logstash/api/service.rb +++ b/logstash-core/lib/logstash/api/service.rb @@ -26,7 +26,7 @@ module LogStash end def started? - !@snapshot.nil? && has_counters? + !@snapshot.nil? && has_counters? end def update(snapshot) diff --git a/logstash-core/lib/logstash/environment.rb b/logstash-core/lib/logstash/environment.rb index 6cfea6868..9f1777498 100644 --- a/logstash-core/lib/logstash/environment.rb +++ b/logstash-core/lib/logstash/environment.rb @@ -29,6 +29,7 @@ module LogStash Setting::String.new("log.format", "plain", true, ["json", "plain"]), Setting::String.new("http.host", "127.0.0.1"), Setting::Port.new("http.port", 9600), + Setting::String.new("http.environment", "production"), ].each {|setting| SETTINGS.register(setting) } module Environment diff --git a/logstash-core/lib/logstash/webserver.rb b/logstash-core/lib/logstash/webserver.rb index 9fbd9718b..6cf8366e3 100644 --- a/logstash-core/lib/logstash/webserver.rb +++ b/logstash-core/lib/logstash/webserver.rb @@ -1,25 +1,25 @@ # encoding: utf-8 require "puma" require "puma/server" -require "sinatra" -require "rack" require "logstash/api/rack_app" module LogStash class WebServer extend Forwardable - attr_reader :logger, :status, :config, :options, :cli_options, :runner, :binder, :events, :http_host, :http_port + attr_reader :logger, :status, :config, :options, :cli_options, :runner, :binder, :events, :http_host, :http_port, :http_environment def_delegator :@runner, :stats DEFAULT_HOST = "127.0.0.1".freeze DEFAULT_PORT = 9600.freeze + DEFAULT_ENVIRONMENT = 'production'.freeze def initialize(logger, options={}) @logger = logger @http_host = options[:http_host] || DEFAULT_HOST @http_port = options[:http_port] || DEFAULT_PORT + @http_environment = options[:http_environment] || DEFAULT_ENVIRONMENT @options = {} @cli_options = options.merge({ :rackup => ::File.join(::File.dirname(__FILE__), "api", "init.ru"), :binds => ["tcp://#{http_host}:#{http_port}"], @@ -37,7 +37,8 @@ module LogStash stop # Just in case - @server = ::Puma::Server.new(LogStash::Api::RackApp.app) + app = LogStash::Api::RackApp.app(logger, http_environment) + @server = ::Puma::Server.new(app) @server.add_tcp_listener(http_host, http_port) @server.run.join diff --git a/logstash-core/spec/api/lib/rack_app_spec.rb b/logstash-core/spec/api/lib/rack_app_spec.rb new file mode 100644 index 000000000..0546df9fb --- /dev/null +++ b/logstash-core/spec/api/lib/rack_app_spec.rb @@ -0,0 +1,88 @@ +require "logstash/api/rack_app" +require "rack/test" + +describe LogStash::Api::RackApp do + include Rack::Test::Methods + + class DummyApp + class RaisedError < StandardError; end + + def call(env) + case env["PATH_INFO"] + when "/good-page" + [200, {}, ["200 OK"]] + when "/service-unavailable" + [503, {}, ["503 service unavailable"]] + when "/raise-error" + raise RaisedError, "Error raised" + else + [404, {}, ["404 Page not found"]] + end + end + end + + let(:logger) { Cabin::Channel.get } + + describe LogStash::Api::RackApp::ApiErrorHandler do + let(:app) do + # Scoping in rack builder is weird, these need to be locals + rack_class = described_class + rack_logger = logger + Rack::Builder.new do + use rack_class, rack_logger + run DummyApp.new + end + end + + it "should let good requests through as normal" do + get "/good-page" + expect(last_response).to be_ok + end + + it "should let through 5xx codes" do + get "/service-unavailable" + expect(last_response.status).to eql(503) + end + + describe "raised exceptions" do + before do + allow(logger).to receive(:error).with(any_args) + get "/raise-error" + end + + it "should return a 500 error" do + expect(last_response.status).to eql(500) + end + + it "should return valid JSON" do + expect { LogStash::Json.load(last_response.body) }.not_to raise_error + end + + it "should log the error" do + expect(logger).to have_received(:error).with(LogStash::Api::RackApp::ApiErrorHandler::LOG_MESSAGE, anything).once + end + end + end + + describe LogStash::Api::RackApp::ApiLogger do + let(:app) do + # Scoping in rack builder is weird, these need to be locals + rack_class = described_class + rack_logger = logger + Rack::Builder.new do + use rack_class, rack_logger + run DummyApp.new + end + end + + it "should log good requests as info" do + expect(logger).to receive(:info).with(LogStash::Api::RackApp::ApiLogger::LOG_MESSAGE, anything).once + get "/good-page" + end + + it "should log 5xx requests as warnings" do + expect(logger).to receive(:warn).with(LogStash::Api::RackApp::ApiLogger::LOG_MESSAGE, anything).once + get "/service-unavailable" + end + end +end diff --git a/logstash-core/spec/api/spec_helper.rb b/logstash-core/spec/api/spec_helper.rb index befead55d..041311b93 100644 --- a/logstash-core/spec/api/spec_helper.rb +++ b/logstash-core/spec/api/spec_helper.rb @@ -46,6 +46,7 @@ class LogStashRunner "log.level" => "debug", "node.name" => "test_agent", "http.port" => rand(9600..9700), + "http.environment" => "test", "config.string" => @config_str, "pipeline.batch.size" => 1, "pipeline.workers" => 1 @@ -60,7 +61,8 @@ class LogStashRunner @runner = Thread.new(agent) do |_agent| _agent.execute end - wait_until_snapshot_received + + wait_until_ready end def stop @@ -71,8 +73,9 @@ class LogStashRunner private - def wait_until_snapshot_received - while !LogStash::Api::Service.instance.started? do + def wait_until_ready + # Wait until the service and pipeline have started + while !(LogStash::Api::Service.instance.started? && agent.pipelines["main"].running?) do sleep 0.5 end end