Merge pull request #1 from apsislabs/feature/logging-improvements

Feature/logging improvements

Author: wkirby

Appraisals

@@ -1,3 +1,4 @@
 appraise 'rails-5.0' do
   gem 'rails', '5.0.0'
+  gem 'tzinfo-data'
 end

Dockerfile

@@ -0,0 +1,16 @@
+FROM ruby:2.5.1-alpine
+MAINTAINER wyatt@apsis.io
+
+RUN apk add --no-cache --update \
+    bash \
+    alpine-sdk \
+    sqlite-dev
+
+ENV APP_HOME /app
+WORKDIR $APP_HOME
+
+COPY . $APP_HOME/
+
+EXPOSE 3000
+
+CMD ["bash"]

README.md

@@ -31,12 +31,28 @@ class PatientInfo < ActiveRecord::Base
 end
 ```
 
+Access is granted on a model level:
+```ruby
+info = new PatientInfo
+info.allow_phi!("allowed_user@example.com", "Customer Service")
+```
+
+or a class:
+```ruby
+PatientInfo.allow_phi!("allowed_user@example.com", "Customer Service")
+```
+
 ## Development
 
 After checking out the repo, run `bin/setup` to install dependencies. Then, run `rake spec` to run the tests. You can also run `bin/console` for an interactive prompt that will allow you to experiment.
 
 To install this gem onto your local machine, run `bundle exec rake install`. To release a new version, update the version number in `version.rb`, and then run `bundle exec rake release`, which will create a git tag for the version, push git commits and tags, and push the `.gem` file to [rubygems.org](https://rubygems.org).
 
+### Docker
+
+* `docker-compose up`
+* `bin/ssh_to_container`
+
 ## Testing
 
     $ bundle exec appraisal rspec spec/phi_attrs_spec.rb

bin/setup

@@ -3,5 +3,5 @@ set -euo pipefail
 IFS=$'\n\t'
 set -vx
 
-bundle install
+bundle check || bundle install
 bundle exec appraisal install

bin/ssh_to_container

@@ -0,0 +1,3 @@
+#! /bin/bash
+
+docker-compose run rails sh

docker-compose.yml

@@ -0,0 +1,18 @@
+version: '3'
+
+services:
+  rails:
+    build: .
+    volumes:
+      - bundle_cache:/bundle
+      - .:/app
+    environment:
+      - BUNDLE_JOBS=5
+      - BUNDLE_PATH=/bundle
+      - BUNDLE_BIN=/bundle/bin
+      - GEM_HOME=/bundle
+    command:
+      - docker/start.sh
+
+volumes:
+  bundle_cache:

docker/start.sh

@@ -0,0 +1,7 @@
+#!/usr/bin/env bash
+
+echo "Beginning Setup"
+/app/bin/setup
+
+echo "Environment Ready"
+tail -f /etc/hosts

gemfiles/rails_5.0.gemfile

@@ -3,5 +3,6 @@
 source "https://rubygems.org"
 
 gem "rails", "5.0.0"
+gem "tzinfo-data"
 
 gemspec path: "../"

lib/phi_attrs.rb

@@ -5,15 +5,18 @@
 require 'phi_attrs/version'
 require 'phi_attrs/configure'
 require 'phi_attrs/railtie' if defined?(Rails)
+require 'phi_attrs/formatter'
 require 'phi_attrs/logger'
 require 'phi_attrs/exceptions'
 require 'phi_attrs/phi_record'
 
 module PhiAttrs
   def phi_model(with: nil, except: nil)
     include PhiRecord
+    logger = ActiveSupport::Logger.new(PhiAttrs.log_path)
+    logger.formatter = Formatter.new
+    file_logger = ActiveSupport::TaggedLogging.new(logger)
 
-    file_logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(PhiAttrs.log_path))
     PhiAttrs::Logger.logger = file_logger
   end
 
@@ -31,5 +34,3 @@ def self.log_path=(value)
     @@log_path = value
   end
 end
-
-

lib/phi_attrs/formatter.rb

@@ -0,0 +1,10 @@
+module PhiAttrs
+  Format = "%s %5s: %s\n".freeze
+
+  # https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L587
+  class Formatter < ::Logger::Formatter
+    def call(severity, timestamp, progname, msg)
+      Format % [format_datetime(timestamp), severity, msg2str(msg)]
+    end
+  end
+end

lib/phi_attrs/phi_record.rb

@@ -29,13 +29,16 @@ def allow_phi!(user_id, reason)
           user_id: user_id,
           reason: reason
         }
-
-        PhiAttrs::Logger.info("PHI Access Enabled for #{user_id}: #{reason}")
+        PhiAttrs::Logger.tagged(PHI_ACCESS_LOG_TAG, name) do
+          PhiAttrs::Logger.info("PHI Access Enabled for #{user_id}: #{reason}")
+        end
       end
 
       def disallow_phi!
         RequestStore.store[:phi_access].delete(name) if RequestStore.store[:phi_access].present?
-        PhiAttrs::Logger.info('PHI access disabled')
+        PhiAttrs::Logger.tagged(PHI_ACCESS_LOG_TAG, name) do
+          PhiAttrs::Logger.info('PHI access disabled')
+        end
       end
     end
 
@@ -46,9 +49,6 @@ def initialize(*args)
       @__phi_access_allowed = false
       @__phi_access_logged = false
 
-      @__phi_log_id = persisted? ? attributes[self.class.primary_key] : object_id
-      @__phi_log_key = "#{PHI_ACCESS_LOG_TAG} #{@__phi_log_id}"
-
       # Wrap attributes with PHI Logger and Access Control
       __phi_wrapped_methods.each { |attr| phi_wrap_method(attr) }
     end
@@ -58,17 +58,17 @@ def __phi_wrapped_methods
     end
 
     def allow_phi!(user_id, reason)
-      PhiAttrs::Logger.tagged(@__phi_log_key) do
+      PhiAttrs::Logger.tagged( *phi_log_keys ) do
         @__phi_access_allowed = true
         @__phi_user_id = user_id
         @__phi_access_reason = reason
 
-        PhiAttrs::Logger.info("PHI Access Enabled for #{user_id}: #{reason}")
+        PhiAttrs::Logger.info("PHI Access Enabled for '#{user_id}': #{reason}")
       end
     end
 
     def disallow_phi!
-      PhiAttrs::Logger.tagged(@__phi_log_key) do
+      PhiAttrs::Logger.tagged(*phi_log_keys) do
         @__phi_access_allowed = false
         @__phi_user_id = nil
         @__phi_access_reason = nil
@@ -91,18 +91,23 @@ def phi_access_reason
 
     private
 
+    def phi_log_keys
+      @__phi_log_id = persisted? ? "Key: #{attributes[self.class.primary_key]}" : "Object: #{object_id}"
+      @__phi_log_keys = [PHI_ACCESS_LOG_TAG, self.class.name, @__phi_log_id]
+    end
+
     def phi_wrap_method(method_name)
       return if self.class.__phi_methods_wrapped.include? method_name
 
       wrapped_method = :"__#{method_name}_phi_wrapped"
       unwrapped_method = :"__#{method_name}_phi_unwrapped"
 
       self.class.send(:define_method, wrapped_method) do |*args, &block|
-        PhiAttrs::Logger.tagged(@__phi_log_key) do
-          raise PhiAttrs::Exceptions::PhiAccessException, "Attempted PHI acces for #{self.class.name} #{@__phi_user_id}" unless phi_allowed?
+        PhiAttrs::Logger.tagged(*phi_log_keys) do
+          raise PhiAttrs::Exceptions::PhiAccessException, "Attempted PHI access for #{self.class.name} #{@__phi_user_id}" unless phi_allowed?
 
           unless @__phi_access_logged
-            PhiAttrs::Logger.info("#{@__phi_user_id} accessing #{self.class.name} #{@__phi_user_id}.\n\t access logging triggered by method: #{method_name}")
+            PhiAttrs::Logger.info("'#{phi_allowed_by}' accessing #{self.class.name}.\n\t access logging triggered by method: #{method_name}")
             @__phi_access_logged = true
           end
 
@@ -111,7 +116,7 @@ def phi_wrap_method(method_name)
       end
 
       # method_name => wrapped_method => unwrapped_method
-      self.class.send(:alias_method, unwrapped_method, method_name) 
+      self.class.send(:alias_method, unwrapped_method, method_name)
       self.class.send(:alias_method, method_name, wrapped_method)
 
       self.class.__phi_methods_wrapped << method_name

spec/phi_attrs_spec.rb

@@ -23,6 +23,7 @@
 
   context 'logging' do
     it 'should log an error when raising an exception' do
+      patient_john # TODO Clean up: Logger.logger isn't defined unless we load something tagged with phi_attrs
       expect(PhiAttrs::Logger.logger).to receive(:error).with('my error message')
 
       expect {
@@ -34,6 +35,52 @@
       expect(PhiAttrs::Logger.logger).to receive(:error)
       expect { patient_john.birthday }.to raise_error(PhiAttrs::Exceptions::PhiAccessException)
     end
+
+    it 'should log when granting phi to instance' do
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      patient_jane.allow_phi! 'test', 'unit tests'
+    end
+
+    it 'should log when granting phi to class' do
+      patient_john # TODO Clean up: Logger.logger isn't defined unless we load something tagged with phi_attrs
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      PatientInfo.allow_phi! 'test', 'unit tests'
+    end
+
+    it 'should log when revokes phi to class' do
+      patient_john # TODO Clean up: Logger.logger isn't defined unless we load something tagged with phi_attrs
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      PatientInfo.disallow_phi!
+    end
+
+    it 'should log when accessing method' do
+      PatientInfo.allow_phi! 'test', 'unit tests'
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      patient_jane.first_name
+    end
+
+    it 'should log once when accessing multiple methods' do
+      PatientInfo.allow_phi! 'test', 'unit tests'
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      patient_jane.first_name
+      patient_jane.birthday
+    end
+
+    it 'should log object_id for unpersisted' do
+      PatientInfo.allow_phi! 'test', 'unit tests'
+      expect(PhiAttrs::Logger.logger).to receive(:tagged).with(PhiAttrs::PHI_ACCESS_LOG_TAG, PatientInfo.name, "Object: #{patient_jane.object_id}").and_call_original
+      expect(PhiAttrs::Logger.logger).to receive(:info)
+      patient_jane.first_name
+    end
+
+    it 'should log id for persisted' do
+      PatientInfo.allow_phi! 'test', 'unit tests'
+      patient_jane.save
+      expect(patient_jane.persisted?).to be true
+      expect(PhiAttrs::Logger.logger).to receive(:tagged).with(PhiAttrs::PHI_ACCESS_LOG_TAG, PatientInfo.name, "Key: #{patient_jane.id}").and_call_original
+      expect(PhiAttrs::Logger.logger).to receive(:info).and_call_original
+      patient_jane.first_name
+    end
   end
 
   context 'instance authorized' do