cleaning up logging

Gemfile.lock

@@ -2,7 +2,6 @@ PATH
   remote: .
   specs:
     thermostat (0.1.0)
-      brogger
       rpi_gpio
       ruby-units
       ruby_i2c
@@ -11,7 +10,6 @@ PATH
 GEM
   remote: https://rubygems.org/
   specs:
-    brogger (0.1.0)
     coderay (1.1.1)
     coveralls (0.8.15)
       json (>= 1.8, < 3)

bin/thermostat

@@ -9,28 +9,31 @@ include Thermostat::HeatIndexCalculator
 def temperature; Unit.new(@sensor.temp, :tempC); end
 def relative_humidity_percent; @sensor.rh; end
 
-Thermostat.logger.level = :debug
+Thermostat.logger.level     = :debug
+Thermostat.logger.subsystem = :hardware
 
 @sensor = RubyI2C::Device::SI70XX.new
 puts "It is #{temperature >> "tempF"} with #{relative_humidity_percent.to_f}% relative humidity making the heat index #{heat_index >> "tempF"}"
 
-cool_controller = Thermostat::HardwareController::RaspberryPi::Relay.new(17)
-heat_controller = Thermostat::HardwareController::RaspberryPi::Relay.new(27)
-fan_controller = Thermostat::HardwareController::RaspberryPi::Relay.new(22)
+controller = Thermostat::Simple::Controller.new cool_relay: Thermostat::HardwareController::RaspberryPi::Relay.new(17),
+                                                fan_relay: Thermostat::HardwareController::RaspberryPi::Relay.new(22),
+                                                heat_relay: Thermostat::HardwareController::RaspberryPi::Relay.new(27),
+                                                cooldown_seconds: 0.25
 
-thermostat = Thermostat::Simple.new cooling_controller: cool_controller,
-                                    fanning_controller: fan_controller,
-                                    heating_controller: heat_controller,
-                                    name: :awesome
+thermostat = Thermostat::Simple.new controller: controller, name: :awesome
 
-thermostat.heat
-sleep 0.75
-thermostat.cooldown
-sleep 0.5
-thermostat.off
-sleep 0.75
-thermostat.cool
-sleep 0.75
-thermostat.cooldown
-sleep 0.5
-thermostat.off
+begin
+  thermostat.heat
+  sleep 0.75
+  thermostat.cooldown
+  sleep 0.5
+  thermostat.off
+  sleep 0.75
+  thermostat.cool
+  sleep 0.75
+  thermostat.cooldown
+  sleep 0.5
+  thermostat.off
+ensure
+  [ 17, 22, 27 ].each { |p| Thermostat::HardwareController::RaspberryPi::Relay.new(p).open }
+end

lib/thermostat.rb

@@ -1,24 +1,22 @@
-require 'brogger'
 require "thermostat/version"
 
 class Thermostat
 
   autoload :Config,              File.join('thermostat', 'config')
   autoload :ConfigLoader,        File.join('thermostat', 'config_loader')
-  autoload :Controller,          File.join('thermostat', 'controller')
-  autoload :Fan,                 File.join('thermostat', 'fan')
   autoload :HardwareController,  File.join('thermostat', 'hardware_controller')
   autoload :HeatIndexCalculator, File.join('thermostat', 'heat_index_calculator')
   autoload :InvalidSetpoint,     File.join('thermostat', 'invalid_setpoint')
   autoload :Logger,              File.join('thermostat', 'logger')
+  autoload :Logging,             File.join('thermostat', 'logging')
   autoload :LoggingAdapter,      File.join('thermostat', 'logging_adapter')
   autoload :Sensor,              File.join('thermostat', 'sensor')
   autoload :Simple,              File.join('thermostat', 'simple')
   autoload :StateMachineQuestions,  File.join('thermostat', 'state_machine_questions')
   autoload :StructInitializer,   File.join('thermostat', 'struct_initializer')
   autoload :Zone,                File.join('thermostat', 'zone')
 
-  extend Logger
+  extend Logging
 
   attr_reader :default_config
 

lib/thermostat/hardware_controller/raspberry_pi.rb

@@ -1,7 +1,7 @@
 class Thermostat::HardwareController
   module RaspberryPi
     extend Forwardable
-    include Thermostat::Logger
+    include Thermostat::Logging
 
     autoload :GPIO, File.join('thermostat', 'hardware_controller', 'raspberry_pi', 'gpio')
     autoload :PinCleaner, File.join('thermostat', 'hardware_controller', 'raspberry_pi', 'pin_cleaner')
@@ -11,7 +11,7 @@ module RaspberryPi
 
 
     def initialize_pin(pin, **args)
-      logger.debug(self.class.name) { "Setting pin #{pin} as #{args[:as]} initialized #{args[:initialize]}" }
+      logger.hardware(:debug) { "Setting pin #{pin} as #{args[:as]} initialized #{args[:initialize]}" }
       setup pin, as: args[:as], initialize: args[:initialize]
     end
 

lib/thermostat/hardware_controller/raspberry_pi/pin_cleaner.rb

@@ -3,7 +3,7 @@ module PinCleaner
 
     def clean_up(pin, numbering=:bcm)
       proc {
-        Thermostat.logger.debug { "Cleaning raspberry pi pin #{pin}" }
+        Thermostat.logger.hardware(:debug) { "Cleaning raspberry pi pin #{pin}" }
         Thermostat::HardwareController::RaspberryPi.gpio.set_numbering numbering
         Thermostat::HardwareController::RaspberryPi.gpio.clean_up pin
      }

lib/thermostat/hardware_controller/raspberry_pi/relay.rb

@@ -5,7 +5,7 @@ class Relay
     include Thermostat::HardwareController::RaspberryPi
 
     def initialize(pin, numbering: :bcm, close_direction: :low)
-      logger.debug(self.class.name) { "Setting up relay on pin #{pin} (numbering: #{numbering}, close_direction: #{close_direction})" }
+      logger.hardware(:debug) { "Setting up relay on pin #{pin} (numbering: #{numbering}, close_direction: #{close_direction})" }
       self.pin = pin
       self.close_direction = close_direction
       set_numbering numbering if numbering
@@ -36,7 +36,7 @@ def open_direction
 
 
     def toggle(dir)
-      logger.debug(self.class.name) { "sending set_#{dir} on pin #{pin}" }
+      logger.hardware(:debug) { "sending set_#{dir} on pin #{pin}" }
       send "set_#{dir}", pin
     end
 

lib/thermostat/logger.rb

@@ -1,25 +1,157 @@
-require 'brogger'
+require 'logger'
 class Thermostat
-  module Logger
+  class Logger < ::Logger
 
-    attr_writer :logger
+    autoload :Formatter, File.join('thermostat', 'logger', 'formatter')
 
-    # TODO Implement multi-logger
-    # http://stackoverflow.com/a/6410202
-    def default_logger(level: :warn)
-      Brogger.new(STDERR).tap do |logger|
-        logger.level = level
-        logger.progname = :thermostat
+    module Subsystem
+      HARDWARE      = 0  # Raspberry Pi / microcontroller information
+      STATE_MACHINE = 1  # State changes
+      CONTROLLER    = 2  # Hardware controller messages
+      SENSOR        = 3  # Temperature, humidity, etc
+      THERMOSTAT    = 4  # General operation messages
+    end
+    include Subsystem
+
+    # DEBUG < INFO < WARN < ERROR < FATAL < UNKNOWN
+    SEVERITY_MAPPING = { debug: DEBUG,     # Low-level information for developers
+                         error: ERROR,     # A handleable error condition
+                         fatal: FATAL,     # An unhandleable error that results in a program crash
+                         info: INFO,       # Generic (useful) information about system operation
+                         unknown: UNKNOWN, # An unknown message that should always be logged
+                         warn: WARN        # A warning
+                       }
+
+    # HARDWARE < STATE_MACHINE < CONTROLLER < SENSOR < THERMOSTAT
+    SUBSYSTEM_MAPPING = { controller:    CONTROLLER,
+                          hartware:      HARDWARE,
+                          thermostat:    THERMOSTAT,
+                          sensor:        SENSOR,
+                          state_machine: STATE_MACHINE
+                        }
+
+    attr_reader :subsystem
+
+    def add(severity, subsystem, message=nil)
+      severity = lookup_severity(severity)
+      subsystem = lookup_subsystem(subsystem)
+      if @logdev.nil? or (severity < @level and subsystem < @subsystem)
+        return true
+      end
+      if message.nil? && block_given?
+        message = yield
       end
+      if message.nil?
+        false
+      else
+        @logdev.write format_message(format_severity(severity), format_subsystem(subsystem), Time.now, message )
+        true
+      end
+    end
+
+
+    def controller(severity=nil, msg=nil, &block)
+      add severity, CONTROLLER, msg, &block
+    end
+
+
+    def debug(subsystem=nil, msg=nil, &block)
+      add DEBUG, subsystem, msg, &block
+    end
+
+
+    def error(subsystem=nil, msg=nil, &block)
+      add ERROR, subsystem, msg, &block
+    end
+
+
+    def fatal(subsystem=nil, msg=nil, &block)
+      add FATAL, subsystem, msg, &block
+    end
+
+
+    def format_message(severity, subsystem, time, message)
+      @formatter.call(severity, subsystem, time, @progname, message)
+    end
+
+
+
+    def hardware(severity=nil, msg=nil, &block)
+      add severity, HARDWARE, msg, &block
+    end 
+
+
+    def info(subsystem=nil, msg=nil, &block)
+      add INFO, subsystem, msg, &block
+    end
+
+
+    def initialize(*)
+      super
+      self.formatter = Formatter.new
+      @subsystem = THERMOSTAT
+    end
+
+
+    def level=(l)
+      super lookup_severity(l)
+    end
+
+
+    def sensor(severity=nil, msg=nil, &block)
+      add severity, SENSOR, msg, &block
+    end 
+
+
+    def state_machine(severity=nil, msg=nil, &block)
+      add severity, STATE_MACHINE, msg, &block
+    end 
+
+
+    def subsystem=(s)
+      @subsystem = lookup_subsystem(s)
+    end
+
+
+    def thermostat(severity=nil, msg=nil, &block)
+      add severity, THERMOSTAT, msg, &block
+    end 
+
+
+    def unknown(subsystem=nil, msg=nil, &block)
+      add UNKNOWN, subsystem, msg, &block
+    end
+
+
+    def warn(subsystem=nil, msg=nil, &block)
+      add WARN, subsystem, msg, &block
+    end
+
+  private
+
+    SUBSYSTEM_LABEL = %w(HARDWARE STATE_MACHINE CONTROLLER SENSOR THERMOSTAT ANY).each(&:freeze).freeze
+
+    def severity_mapping; SEVERITY_MAPPING; end
+    def subsystem_mapping; SUBSYSTEM_MAPPING; end
+
+
+    def format_subsystem(s)
+      SUBSYSTEM_LABEL[s] || SUBSYSTEM_LEVEL[-1]
+    end
+
+
+    def lookup_severity(s)
+      lookup(s, severity_mapping, UNKNOWN)
+    end
+
+
+    def lookup_subsystem(s)
+      lookup(s, subsystem_mapping, THERMOSTAT)
     end
 
 
-    def logger
-      @logger ||= if self == Thermostat
-                    default_logger
-                  else
-                    Thermostat.logger
-                  end
+    def lookup(s,m,d)
+      s.is_a?(Integer) ? s : m.fetch(s.to_s.downcase.intern, d)
     end
 
   end

lib/thermostat/logger/formatter.rb

@@ -0,0 +1,20 @@
+class Thermostat::Logger
+  class Formatter < ::Logger::Formatter
+
+    def call(severity, subsystem, time, progname, msg)
+      format % [ time.utc.iso8601, progname, $$, subsystem, severity, msg2str(msg) ]
+    end
+
+
+    def format
+      # time [progname.pid] subsystem.severity: msg
+      "%s [%s.%d] %13s.%5s: %s\n"
+    end
+
+
+    def msg2str(*)
+      super.strip
+    end
+
+  end
+end

lib/thermostat/logging.rb

@@ -0,0 +1,23 @@
+class Thermostat
+  module Logging
+
+    # TODO Implement multi-logger
+    # http://stackoverflow.com/a/6410202
+    def self.default_logger(level: :warn)
+      Thermostat::Logger.new(STDERR).tap do |logger|
+        logger.level = level
+        logger.progname = :thermostat
+      end
+    end
+
+
+    def logger
+      @logger ||= if self == Thermostat
+                    Thermostat::Logging.default_logger
+                  else
+                    Thermostat.logger
+                  end
+    end
+
+  end
+end

lib/thermostat/logging_adapter.rb

@@ -1,12 +1,12 @@
 require 'statesman'
 class Thermostat
   class LoggingAdapter < Statesman::Adapters::Memory
-    include Thermostat::Logger
+    include Thermostat::Logging
 
     def create(from, to, metadata={})
-      logger.debug(@parent_model) { "Beginning transition from #{from} to #{to}" }
+      logger.state_machine(:debug) { "Beginning transition from #{from} to #{to}" }
       t = super
-      logger.debug(@parent_model) { "Finished transition from #{from} to #{to}" }
+      logger.state_machine(:debug) { "Finished transition from #{from} to #{to}" }
       t
     end
 

lib/thermostat/sensor/temperature.rb

@@ -43,7 +43,7 @@ def unitify_temp(t)
       else
         m = "don't know how to handle a #{t.class} temperature"
         if defined? logger
-          logger.warn m
+          logger.sensor(:error) { m }
           return nil
         else
           raise m