Merge branch 'feature/log-requests-and-errors' into 'master'

Log requests and errors

proper logging

See merge request !6

17 files changed, 154 insertions, 84 deletions

diff --git a/lib/nickserver/adapters/http.rb b/lib/nickserver/adapters/http.rb
new file mode 100644
index 0000000..b0ba728
--- /dev/null
+++ b/lib/nickserver/adapters/http.rb
@@ -0,0 +1,21 @@
+require 'nickserver/adapters'
+require 'nickserver/config'
+require 'http'
+
+module Nickserver::Adapters
+  class Http
+
+    def get(url, options = {})
+      response = HTTP.get url,
+        params: options[:query],
+        ssl_context: ctx
+      return response.code, response.to_s
+    end
+
+    def ctx
+      OpenSSL::SSL::SSLContext.new.tap do |ctx|
+        ctx.ca_file = Nickserver::Config.hkp_ca_file
+      end
+    end
+  end
+end
diff --git a/lib/nickserver/daemon.rb b/lib/nickserver/daemon.rb
index 9cc1af7..12ed30e 100644
--- a/lib/nickserver/daemon.rb
+++ b/lib/nickserver/daemon.rb
@@ -176,6 +176,7 @@ module Nickserver
         $stdout.reopen(log_path, 'a')
         $stderr.reopen $stdout
         $stdout.sync = true
+        $stderr.sync = true
       else
         # redirect to /dev/null
         $stdin.reopen '/dev/null'
@@ -255,6 +256,7 @@ module Nickserver
         puts "\nShutting down..."
         exit(0)
       end
+      Config.log_file = STDOUT
       yield
       exit(0)
     end
diff --git a/lib/nickserver/dispatcher.rb b/lib/nickserver/dispatcher.rb
index 869f721..71e71cf 100644
--- a/lib/nickserver/dispatcher.rb
+++ b/lib/nickserver/dispatcher.rb
@@ -39,10 +39,6 @@ module Nickserver
 
     def handle(request)
       handler_chain.handle request
-    rescue RuntimeError => exc
-      puts "Error: #{exc}"
-      puts exc.backtrace
-      ErrorResponse.new(exc.to_s)
     end
 
     def handler_chain
@@ -62,9 +58,10 @@ module Nickserver
     end
 
     def proxy_error_response
-      exception = handler_chain.rescued_exceptions.first
-      if exception
-        Nickserver::Response.new(502, exception.to_s)
+      exc = handler_chain.rescued_exceptions.first
+      if exc
+        Nickserver::Response.new 502,
+          JSON.dump(error: exc.to_s)
       end
     end
 
diff --git a/lib/nickserver/logging_responder.rb b/lib/nickserver/logging_responder.rb
new file mode 100644
index 0000000..6eb756f
--- /dev/null
+++ b/lib/nickserver/logging_responder.rb
@@ -0,0 +1,18 @@
+module Nickserver
+  class LoggingResponder
+
+    def initialize(responder, logger)
+      @responder = responder
+      @logger = logger
+    end
+
+    def respond(status, body)
+      logger.info " -> #{status}"
+      responder.respond(status, body)
+    end
+
+    protected
+
+    attr_reader :responder, :logger
+  end
+end
diff --git a/lib/nickserver/reel_server.rb b/lib/nickserver/reel_server.rb
index d2a95ba..c378aca 100644
--- a/lib/nickserver/reel_server.rb
+++ b/lib/nickserver/reel_server.rb
@@ -1,8 +1,11 @@
 silence_warnings do
   require 'reel'
 end
+require 'logger'
+require 'nickserver/config'
 require 'nickserver/adapters/celluloid_http'
 require 'nickserver/dispatcher'
+require 'nickserver/logging_responder'
 
 module Nickserver
   class ReelServer < Reel::Server::HTTP
@@ -12,6 +15,7 @@ module Nickserver
     end
 
     def initialize(host = "127.0.0.1", port = 3000)
+      Celluloid.logger = logger
       super(host, port, &method(:on_connection))
     end
 
@@ -23,17 +27,28 @@ module Nickserver
 
     def on_connection(connection)
       connection.each_request do |request|
-        handler = handler_for(request)
-        handler.respond_to params(request), request.headers
+        handle_request(request)
       end
     end
 
 
     protected
 
+    def handle_request(request)
+      logger.info "#{request.method} #{request.uri}"
+      logger.debug "  #{params(request)}"
+      handler = handler_for(request)
+      handler.respond_to params(request), request.headers
+    rescue StandardError => e
+      logger.error e
+      logger.error e.backtrace.join "\n  "
+      request.respond 500, "{}"
+    end
+
     def handler_for(request)
       # with reel the request is the responder
-      Dispatcher.new(request)
+      responder = LoggingResponder.new(request, logger)
+      Dispatcher.new(responder)
     end
 
     def params(request)
@@ -44,5 +59,8 @@ module Nickserver
       end
     end
 
+    def logger
+      @logger ||= ::Logger.new Config.log_file
+    end
   end
 end
diff --git a/lib/nickserver/source.rb b/lib/nickserver/source.rb
index edc57e9..dc0669a 100644
--- a/lib/nickserver/source.rb
+++ b/lib/nickserver/source.rb
@@ -3,7 +3,9 @@ require 'nickserver/adapters/celluloid_http'
 module Nickserver
   class Source
 
-    def initialize(adapter = Nickserver::Adapters::CelluloidHttp.new)
+    DEFAULT_ADAPTER_CLASS = Nickserver::Adapters::CelluloidHttp
+
+    def initialize(adapter = DEFAULT_ADAPTER_CLASS.new)
       @adapter = adapter
     end
 
diff --git a/test/functional/bin_test.rb b/test/functional/bin_test.rb
index bc15e38..ef2d74e 100644
--- a/test/functional/bin_test.rb
+++ b/test/functional/bin_test.rb
@@ -4,19 +4,45 @@ require 'minitest/hell'
 
 class BinTest < Minitest::Test
 
+  def teardown
+    run_command "stop"
+  end
+
   def test_bin_loading
     assert_command_runs("version")
-    assert_equal 0, $?.exitstatus
+  end
+
+  def test_not_running_by_default
+    assert_stopped
+  end
+
+  def test_start
+    run_command "start"
+    assert_running
   end
 
   protected
 
+  def assert_running
+    status = run_command "status"
+    assert_includes status, "Nickserver running"
+  end
+
+  def assert_stopped
+    status = run_command "status"
+    assert_includes status, "No nickserver processes are running."
+  end
+
   def assert_command_runs(command)
-    out = `#{path_to_executable} #{command} 2>&1`
+    out = run_command command
     assert ($?.exitstatus == 0),
       "failed to run 'nickserver #{command}':\n #{out}"
   end
 
+  def run_command(command)
+    `#{path_to_executable} #{command} 2>&1`
+  end
+
   def path_to_executable
     File.expand_path(File.dirname(__FILE__) + '/../../bin/nickserver')
   end
diff --git a/test/integration/dispatcher_test.rb b/test/integration/dispatcher_test.rb
index 4f13e6b..b551e87 100644
--- a/test/integration/dispatcher_test.rb
+++ b/test/integration/dispatcher_test.rb
@@ -55,11 +55,11 @@ class Nickserver::DispatcherTest < Minitest::Test
     assert_response success
   end
 
-  def test_email_via_hkp_nicknym_unreachable
+  def test_email_not_found_hkp_nicknym_unreachable
     handle address: ['valid@email.tld'], headers: { "Host" => "http://nickserver.me" }
     stub_nicknym_raises
     hkp_source.expect :query, nil, [Nickserver::EmailAddress]
-    assert_response response(status: 502, content: "HTTP::ConnectionError")
+    assert_response http_connection_error
   end
 
   def test_email_via_nicknym
@@ -126,6 +126,11 @@ class Nickserver::DispatcherTest < Minitest::Test
     response status: 500, content: "500 #{msg}\n"
   end
 
+  def http_connection_error
+    response status: 502,
+      content: JSON.dump(error: "HTTP::ConnectionError")
+  end
+
   def response(options)
     Nickserver::Response.new(options[:status], options[:content])
   end
diff --git a/test/integration/hkp_test.rb b/test/integration/hkp_test.rb
index 7d4bb6b..da128c2 100644
--- a/test/integration/hkp_test.rb
+++ b/test/integration/hkp_test.rb
@@ -5,17 +5,6 @@ require 'nickserver/hkp/source'
 class HkpTest < Minitest::Test
   include HttpStubHelper
 
-  def setup
-    super
-    Celluloid.boot
-  end
-
-  def teardown
-    Celluloid.shutdown
-    super
-  end
-
-
   def test_key_info_expired
     fetch_key_info(:hkp_vindex_result, 'lemur@leap.se') do |keys|
       assert_equal 1, keys.length, 'should find a single key'
diff --git a/test/integration/nicknym_test.rb b/test/integration/nicknym_test.rb
deleted file mode 100644
index bfcd7e1..0000000
--- a/test/integration/nicknym_test.rb
+++ /dev/null
@@ -1,11 +0,0 @@
-require 'test_helper'
-require 'support/client_integration_test'
-require 'nickserver/nicknym/source'
-
-class NicknymClientTest < ClientIntegrationTest
-
-  def test_truth
-    assert true
-  end
-
-end
diff --git a/test/integration/nickserver_test.rb b/test/integration/nickserver_test.rb
index 06d6e29..5dffcd2 100644
--- a/test/integration/nickserver_test.rb
+++ b/test/integration/nickserver_test.rb
@@ -1,4 +1,5 @@
 require 'test_helper'
+require 'support/celluloid_test'
 require 'support/http_stub_helper'
 require 'nickserver/server'
 require 'json'
@@ -15,24 +16,15 @@ require 'json'
 #
 # (1) We mock the http adapter. So no network is required.
 #
-# (2) We actually start the nickserver on 127.0.0.1 and talk to it via http.
+# (2) We actually start the Reelserver on 127.0.0.1 and talk to it via http.
+#     In order to run the Reelserver properly this is a celluloid test.
 #
 # (3) the "Host" header for requests to nickserver must be set (or Config.domain set)
 #
 
-class NickserverTest < Minitest::Test
+class NickserverTest < CelluloidTest
   include HttpStubHelper
 
-  def setup
-    super
-    Celluloid.boot
-  end
-
-  def teardown
-    Celluloid.shutdown
-    super
-  end
-
   def test_GET_key_by_email_address_served_via_SKS
     uid    = 'cloudadmin@leap.se'
     key_id = 'E818C478D3141282F7590D29D041EB11B1647490'
diff --git a/test/remote/celluloid_http_test.rb b/test/remote/celluloid_http_test.rb
index 46a5259..da5f5d7 100644
--- a/test/remote/celluloid_http_test.rb
+++ b/test/remote/celluloid_http_test.rb
@@ -1,22 +1,15 @@
 require 'test_helper'
+require 'support/celluloid_test'
 require 'nickserver/adapters/celluloid_http'
 
-class Nickserver::Adapters::CelluloidHttpTest < Minitest::Test
-
-  def setup
-    super
-    Celluloid.boot
-  end
-
-  def teardown
-    Celluloid.shutdown
-    super
-  end
+class Nickserver::Adapters::CelluloidHttpTest < CelluloidTest
 
   def test_https_for_hkp
     url = Nickserver::Config.hkp_url
     status, _body = adapter.get url
     assert_equal 404, status
+  rescue HTTP::ConnectionError => e
+    skip "could not talk to hkp server: #{e}"
   end
 
   protected
diff --git a/test/remote/hkp_source_test.rb b/test/remote/hkp_source_test.rb
index aabc4d3..103b8ad 100644
--- a/test/remote/hkp_source_test.rb
+++ b/test/remote/hkp_source_test.rb
@@ -1,17 +1,8 @@
 require 'test_helper'
+require 'support/celluloid_test'
 require 'nickserver/hkp/source'
 
-class RemoteHkpSourceTest < Minitest::Test
-
-  def setup
-    super
-    Celluloid.boot
-  end
-
-  def teardown
-    Celluloid.shutdown
-    super
-  end
+class RemoteHkpSourceTest < CelluloidTest
 
   def test_key_info
     uid = 'elijah@riseup.net'
@@ -45,5 +36,7 @@ class RemoteHkpSourceTest < Minitest::Test
       assert_equal 200, status
       yield keys
     end
+  rescue HTTP::ConnectionError => e
+    skip "could not talk to hkp server: #{e}"
   end
 end
diff --git a/test/remote/nicknym_source_test.rb b/test/remote/nicknym_source_test.rb
index b38a991..e2896ca 100644
--- a/test/remote/nicknym_source_test.rb
+++ b/test/remote/nicknym_source_test.rb
@@ -1,21 +1,12 @@
 require 'test_helper'
+require 'support/celluloid_test'
 require 'nickserver/nicknym/source'
 require 'nickserver/email_address'
 
 #
 # Please note the Readme.md file in this directory
 #
-class RemoteNicknymSourceTest < Minitest::Test
-
-  def setup
-    super
-    Celluloid.boot
-  end
-
-  def teardown
-    Celluloid.shutdown
-    super
-  end
+class RemoteNicknymSourceTest < CelluloidTest
 
   def test_availablility_check
     source.available_for? 'mail.bitmask.net'
diff --git a/test/support/client_integration_test.rb b/test/support/celluloid_test.rb
index b05db73..ddcfcbb 100644
--- a/test/support/client_integration_test.rb
+++ b/test/support/celluloid_test.rb
@@ -1,8 +1,9 @@
-class ClientIntegrationTest
+class CelluloidTest < Minitest::Test
 
   def setup
     super
     Celluloid.boot
+    Celluloid.logger = nil
   end
 
   def teardown
diff --git a/test/support/http_stub_helper.rb b/test/support/http_stub_helper.rb
index cb9b578..dd3d1b2 100644
--- a/test/support/http_stub_helper.rb
+++ b/test/support/http_stub_helper.rb
@@ -1,7 +1,9 @@
+require 'nickserver/source'
+
 module HttpStubHelper
 
   def stubbing_http
-    Nickserver::Adapters::CelluloidHttp.stub :new, adapter do
+    Nickserver::Source::DEFAULT_ADAPTER_CLASS.stub :new, adapter do
       yield
     end
     adapter.verify
diff --git a/test/unit/logging_responder_test.rb b/test/unit/logging_responder_test.rb
new file mode 100644
index 0000000..bb6c4a0
--- /dev/null
+++ b/test/unit/logging_responder_test.rb
@@ -0,0 +1,31 @@
+require 'test_helper'
+require 'nickserver/logging_responder'
+
+module Nickserver
+  class LoggingResponderTest < Minitest::Test
+
+    def test_responds_and_logs
+      logger.expect :info, nil, [" -> 200"]
+      respond_to 200, "body"
+      logger.verify
+    end
+
+    protected
+
+    def respond_to(*args)
+      responder.expect :respond, nil, args
+      logging_responder = LoggingResponder.new responder, logger
+      logging_responder.respond(*args)
+      responder.verify
+    end
+
+    def responder
+      @responder ||= Minitest::Mock.new
+    end
+
+    def logger
+      @logger ||= Minitest::Mock.new
+    end
+
+  end
+end