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