Logging

Twirp does not provide a logger, but logs can be implemented either by using Rack middleware or by using request life-cycle hooks. Is the same as any other integration like server stats, error reporting or generic authorization checks.

Here are a few examples to configure logging.

Setup example

There are many ways to mount a Twirp-Ruby service handler as a Rack app. One of those ways is by making a rakup config.ru file. This example could be easily deployed as a Heroku Rack App, and works as example for other configuration.

This config.ru file mounts the example HelloWorldHandler as a Rack app.

require './helloworld' # your service definition and handler

handler = HelloWorldHandler.new()
service = HelloWorld::HelloWorldService.new(handler)
run service

Log every request with Rack Middleware

The simplest way to log every request is using Rack::CommonLogger middleware, which prints every request in the Apache common log format:

require './helloworld' # your service definition and handler
require 'logger'

logger = Logger.new('log/app.log')
use Rack::CommonLogger, logger

handler = HelloWorldHandler.new(logger)
service = HelloWorld::HelloWorldService.new(handler)
run service

The caveat for using Rack middleware is that it works on the HTTP level, which doesn't have some specific information about the Twirp service; error responses have the HTTP status code (404, 400, 500, etc.) but not the specific Twirp error code (not_found, invalid_argument, internal, etc.). This may be fine in most cases. Example logged requests look like this:

127.0.0.1 - foo [10/Oct/2000:13:55:36 -0700] "POST /twirp/example.HelloWorld/Hello HTTP/1.0" 200 2326
127.0.0.1 - foo [10/Oct/2000:13:55:37 -0700] "POST /twirp/example.HelloWorld/Other HTTP/1.0" 404 326

Custom logging with Service Hooks

Twirp service hooks have access to the serialized request parameters and other information from env. The following example logs every request with the time it took to complete.

# Setup a Twirp service with hooks to log every request.
def setup_logging_hooks(svc, logger)
  svc.before do |rack_env, env|
    env[:request_start_time] = Time.now
  end

  svc.on_success do |env|
    logger.info(format_log(svc, env, nil))
  end

  svc.on_error do |twerr, env|
    logger.info(format_log(svc, env, twerr))
  end

  svc.exception_raised do |e, env|
    # Log uncaught exception stacktraces. This is in addition to the on_error hook,
    # that already logs the request internal error that results form this exception.
    logger.error("[Exception] #{e}\n#{e.backtrace.join("\n")}")
  end
end

# Format log for a Twirp service request.
def format_log(svc, env, twerr)
  code = twerr ? twerr.to_s : 'OK'
  duration = duration_ms_since(env[:request_start_time])
  return "#{svc.service_name}.#{env[:rpc_method]} [#{duration}ms] #{twerr.to_s}"
end

def duration_ms_since(start)
  return 0 unless start
  ((Time.now - start) * 1000).to_i
end

Use the method setup_logging_hooks on the servie in the config.ru file:

require 'logger'
require './helloworld' # your service definition and handler

logger = Logger.new('log/app.log')

handler = HelloWorldHandler.new(logger)
service = HelloWorld::HelloWorldService.new(handler)
setup_logging_hooks(service, logger)
run service

This approach requires more thinking, but it grants full control. The Twirp env passed to the hooks has information about the request env[:rpc_method] and env[:input], and the response env[:output]. If you want you could include the request and response parameters in the logs, maybe filtering protected parameters like :password or any other logic as needed.

Using the logger in the service handler

If the logger is a global variable, then simply access that logger from the handler methods. But maybe a better approach is to use dependency injection; define a @logger variable in your handler, and initialize it on the constructor:

logger = Logger.new('log/app.log')
handler = HelloWorldHandler.new(logger)