Use Logger class instead of puts-ing and allow configuration

closes #14

README.md

@@ -408,9 +408,7 @@ Now don't forget to go back to your Facebook developer console and change the ad
 
 ## Coming next
 
-* Proper implementation of logging (for now it's just `p` and `puts` statements sprinkled around the code) with ability to choose a logging level.
-
-* More powerful DSL for parsing user input and binding it to commands.   
+* More powerful DSL for parsing user input and binding it to commands.
 
 * NLP integration with Wit.AI (that allow for more things then the built-in NLP capabilities of Messenger platform, including a wrapper around Wit's interactive learning methods) is in the works and will be added to the gem some time in 2018...
 

lib/rubotnik.rb

@@ -15,31 +15,43 @@
 require 'ui/quick_replies'
 require 'sinatra'
 require 'facebook/messenger'
+require 'logger'
+
 include Facebook::Messenger
 
 module Rubotnik
-  def self.subscribe(token)
-    Facebook::Messenger::Subscriptions.subscribe(access_token: token)
-  end
+  class << self
+    attr_writer :logger
+
+    def logger
+      @logger ||= Logger.new($stdout).tap do |log|
+        log.progname = self.name
+      end
+    end
 
-  def self.route(event, &block)
-    if [:message, :postback].include?(event)
-      Bot.on event do |e|
-        case e
-        when Facebook::Messenger::Incoming::Message
-          Rubotnik::MessageDispatch.new(e).route(&block)
-        when Facebook::Messenger::Incoming::Postback
-          Rubotnik::PostbackDispatch.new(e).route(&block)
+    def route(event, &block)
+      if [:message, :postback].include?(event)
+        Bot.on event do |e|
+          case e
+          when Facebook::Messenger::Incoming::Message
+            Rubotnik::MessageDispatch.new(e).route(&block)
+          when Facebook::Messenger::Incoming::Postback
+            Rubotnik::PostbackDispatch.new(e).route(&block)
+          end
         end
+      else
+        Bot.on(event, &block)
       end
-    else
-      Bot.on(event, &block)
     end
-  end
 
-  def self.set_profile(*payloads)
-    payloads.each do |payload|
-      Facebook::Messenger::Profile.set(payload, access_token: ENV['ACCESS_TOKEN'])
+    def subscribe(token)
+      Facebook::Messenger::Subscriptions.subscribe(access_token: token)
+    end
+
+    def set_profile(*payloads)
+      payloads.each do |payload|
+        Facebook::Messenger::Profile.set(payload, access_token: ENV['ACCESS_TOKEN'])
+      end
     end
   end
 end

lib/rubotnik/message_dispatch.rb

@@ -20,7 +20,7 @@ def route(&block)
       if @user.current_command
         command = @user.current_command
         execute(command)
-        puts "Command #{command} is executed for user #{@user.id}"
+        Rubotnik.logger.info "Command #{command} is executed for user #{@user.id}"
       else
         bind_commands(&block)
       end
@@ -54,20 +54,20 @@ def bind(*regex_strings, all: false, to: nil, reply_with: {})
 
     def handle_command(to, reply_with)
       if reply_with.empty?
-        puts "Command #{to} is executed for user #{@user.id}"
+        Rubotnik.logger.info "Command #{to} is executed for user #{@user.id}"
         execute(to)
         @user.reset_command
-        puts "Command is reset for user #{@user.id}"
+        Rubotnik.logger.info "Command is reset for user #{@user.id}"
       else
         say(reply_with[:text], quick_replies: reply_with[:quick_replies])
         @user.assign_command(to)
-        puts "Command #{to} is set for user #{@user.id}"
+        Rubotnik.logger.info "Command #{to} is set for user #{@user.id}"
       end
     end
 
     def default
       return if @matched
-      puts 'None of the commands were recognized' # log
+      Rubotnik.logger.info 'None of the commands were recognized'
       yield
       @user.reset_command
     end

lib/rubotnik/postback_dispatch.rb

@@ -31,7 +31,7 @@ def bind(regex_string, to: nil, reply_with: {})
       return unless @postback.payload == regex_string.upcase
       clear_user_state
       @matched = true
-      puts "Matched #{regex_string} to #{to.nil? ? 'block' : to}"
+      Rubotnik.logger.info "Matched #{regex_string} to #{to.nil? ? 'block' : to}"
       if block_given?
         yield
         return
@@ -42,13 +42,13 @@ def bind(regex_string, to: nil, reply_with: {})
     def handle_command(to, reply_with)
       if reply_with.empty?
         execute(to)
-        puts "Command #{to} is executed for user #{@user.id}"
+        Rubotnik.logger.info "Command #{to} is executed for user #{@user.id}"
         @user.reset_command
-        puts "Command is reset for user #{@user.id}"
+        Rubotnik.logger.info "Command is reset for user #{@user.id}"
       else
         say(reply_with[:message], quick_replies: reply_with[:quick_replies])
         @user.assign_command(to)
-        puts "Command #{to} is set for user #{@user.id}"
+        Rubotnik.logger.info "Command #{to} is set for user #{@user.id}"
       end
     end
 

lib/rubotnik/user_store.rb

@@ -17,18 +17,18 @@ def add(user)
     @users << user
     user = @users.last
     if user
-      p "user #{user.inspect} added to store"
-      p "we got #{@users.count} users: #{@users}"
+      Rubotnik.logger.info "user #{user.inspect} added to store"
+      Rubotnik.logger.info "we got #{@users.count} users: #{@users}"
     else
-      p 'user not found in store yet'
+      Rubotnik.logger.info 'user not found in store yet'
     end
     user
   end
 
   def find(id)
     user = @users.find { |u| u.id == id }
-    p "user #{user} found in store" if user
-    p "we got #{@users.count} users: #{@users}" if user
+    Rubotnik.logger.info "user #{user} found in store" if user
+    Rubotnik.logger.info "we got #{@users.count} users: #{@users}" if user
     user
   end
 end

spec/rubotnik_spec.rb

@@ -5,6 +5,19 @@
     expect(Rubotnik::VERSION).not_to be nil
   end
 
+  describe 'logger' do
+    it 'allows logging' do
+      described_class.logger.info 'aaaa'
+    end
+
+    it 'allows overriding the logger' do
+      logger_double = double(:logger)
+      described_class.logger = logger_double
+      expect(logger_double).to receive(:info)
+      described_class.logger.info 'xxx'
+    end
+  end
+
   describe 'subscribe' do
     it 'subscribes to a fb page' do
       token = 'xxx'