From 51c84f3cfc98a816523475b2b2b07ba57ae49fc8 Mon Sep 17 00:00:00 2001
From: "S. Brent Faulkner" <sbfaulkner@gmail.com>
Date: Fri, 7 Jul 2017 21:05:11 -0400
Subject: [PATCH] Ruby logger (#251)

* Add logger for ruby environment

* Update readme and example for ruby logger

* ruby-env: log load time for user code
---
 environments/ruby/README.md              |  5 +++--
 environments/ruby/fission/context.rb     |  5 +++++
 environments/ruby/fission/handler.rb     |  8 ++++++--
 environments/ruby/fission/specializer.rb | 12 ++++++++++--
 environments/ruby/server.rb              |  3 ++-
 examples/ruby/request_data.rb            | 11 ++++++-----
 6 files changed, 32 insertions(+), 12 deletions(-)

diff --git a/environments/ruby/README.md b/environments/ruby/README.md
index 01de1a4a..0e4ea5e9 100644
--- a/environments/ruby/README.md
+++ b/environments/ruby/README.md
@@ -9,8 +9,9 @@ The environment works via convention where you create a Ruby method
 called `handler` with a single optional argument, a `Fission::Context`
 object.
 
-The `Fission::Context` object gives access to the Rack env, and a
-request object. Please see `fission/context.rb` for the public api.
+The `Fission::Context` object gives access to the Rack env, a
+request object, and a logger. Please see `fission/context.rb` for the
+public api.
 
 The `Fission::Request` object is a subclass of `Rack::Request` and
 provides access to parameters and headers. See `fission/request.rb`
diff --git a/environments/ruby/fission/context.rb b/environments/ruby/fission/context.rb
index 93dd41a2..9e893833 100644
--- a/environments/ruby/fission/context.rb
+++ b/environments/ruby/fission/context.rb
@@ -1,9 +1,14 @@
 # frozen_string_literal: true
 
 require_relative 'request'
+require 'forwardable'
 
 module Fission
   class Context
+    extend Forwardable
+
+    def_instance_delegator :request, :logger
+
     attr_reader :env
 
     def initialize(env)
diff --git a/environments/ruby/fission/handler.rb b/environments/ruby/fission/handler.rb
index ed97318b..c11d36ad 100644
--- a/environments/ruby/fission/handler.rb
+++ b/environments/ruby/fission/handler.rb
@@ -5,14 +5,18 @@ require_relative 'context'
 module Fission
   module Handler
     def self.call(env)
+      context = Context.new(env)
+
       response = if method(:handler).arity > 0
-        handler(Context.new(env))
+        handler(context)
       else
         handler
       end
 
       response.is_a?(Array) ? response : Rack::Response.new([response]).finish
-    rescue
+
+    rescue => e
+      context.logger.error(%(Function failed - #{e}\n#{e.backtrace.join("\n")}))
       Rack::Response.new(['500 Internal Server Error'], 500, {}).finish
     end
   end
diff --git a/environments/ruby/fission/specializer.rb b/environments/ruby/fission/specializer.rb
index 2bfdb414..a6b1dce8 100644
--- a/environments/ruby/fission/specializer.rb
+++ b/environments/ruby/fission/specializer.rb
@@ -1,13 +1,21 @@
 # frozen_string_literal: true
+require 'benchmark'
 
 module Fission
   CODE_PATH = '/userfunc/user'
 
   module Specializer
     def self.call(env)
-      load CODE_PATH
+      request = Request.new(env)
+
+      request.logger.info("Codepath defaulting to #{CODE_PATH}")
+      time = Benchmark.measure { load CODE_PATH }
+      request.logger.info("User code loaded in #{(time.real * 1000).round(3)}ms")
+
       Rack::Response.new([], 201).finish
-    rescue
+
+    rescue => e
+      request.logger.error(%(Specialization failed - #{e}\n#{e.backtrace.join("\n")}))
       Rack::Response.new(['500 Internal Server Error'], 500, {}).finish
     end
   end
diff --git a/environments/ruby/server.rb b/environments/ruby/server.rb
index a6f09b74..6232f750 100644
--- a/environments/ruby/server.rb
+++ b/environments/ruby/server.rb
@@ -1,12 +1,13 @@
 # frozen_string_literal: true
 
 require 'rack'
+require 'logger'
 
 require_relative 'fission/specializer'
 require_relative 'fission/handler'
 
 app = Rack::Builder.new do
-  use Rack::CommonLogger, $stderr
+  use Rack::Logger, Logger::DEBUG
 
   map "/specialize" do
     run Fission::Specializer
diff --git a/examples/ruby/request_data.rb b/examples/ruby/request_data.rb
index cc17b283..e05cc10a 100644
--- a/examples/ruby/request_data.rb
+++ b/examples/ruby/request_data.rb
@@ -1,18 +1,19 @@
 # frozen_string_literal: true
 def handler(context)
-  request = context.request
+  context.logger.info("Received request")
+
   msg = <<~MSG
     ---ENV---
-    #{request.env.map { |h| h.join('=') }.join("\n") }
+    #{context.request.env.map { |h| h.join('=') }.join("\n") }
 
     ---HEADERS---
-    #{request.headers.map { |h| h.join(': ') }.join("\n") }
+    #{context.request.headers.map { |h| h.join(': ') }.join("\n") }
 
     ---PARAMS---
-    #{request.params.map { |h| h.join('=') }.join("\n") }
+    #{context.request.params.map { |h| h.join('=') }.join("\n") }
 
     --BODY--
-    #{request.body.read}
+    #{context.request.body.read}
   MSG
 
   Rack::Response.new([msg]).finish