From f6ae1ac8ae20a7505bf557318a0108cf08c935c3 Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 22:11:46 +0100
Subject: [PATCH 1/9] Fix bug with non-idempotent REST requests

params is the body for the #send_request method when the very is POST/PUT, so the previous code failed with all non-GET requests
---
 lib/ably/rest/client.rb             | 12 ++------
 spec/acceptance/rest/client_spec.rb | 46 +++++++++++++++++++++++++++++
 2 files changed, 48 insertions(+), 10 deletions(-)

diff --git a/lib/ably/rest/client.rb b/lib/ably/rest/client.rb
index 713751916..3289eb18b 100644
--- a/lib/ably/rest/client.rb
+++ b/lib/ably/rest/client.rb
@@ -439,22 +439,14 @@ def send_request(method, path, params, options)
         max_retry_duration = http_defaults.fetch(:max_retry_duration)
         requested_at       = Time.now
         retry_count        = 0
-        request_id         = nil
-        if add_request_ids
-          params = if params.nil?
-            {}
-          else
-            params.dup
-          end
-          request_id = SecureRandom.urlsafe_base64(10)
-          params[:request_id] = request_id
-        end
+        request_id         = SecureRandom.urlsafe_base64(10) if add_request_ids
 
         begin
           use_fallback = can_fallback_to_alternate_ably_host? && retry_count > 0
 
           connection(use_fallback: use_fallback).send(method, path, params) do |request|
             if add_request_ids
+              request.params[:request_id] = request_id
               request.options.context = {} if request.options.context.nil?
               request.options.context[:request_id] = request_id
             end
diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index cadecd066..29a228985 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1062,6 +1062,52 @@ def level=(new_level)
         end
 
         context 'when specifying fallback hosts', :webmock do
+        context 'with option add_request_ids: true and REST operations with a message body' do
+          let(:client_options) { default_options.merge({ key: api_key, add_request_ids: true }) }
+          let(:channel_name) { random_str }
+          let(:channel) { client.channels.get(channel_name) }
+
+          context 'with mocks to inspect the params', :webmock do
+            before do
+              stub_request(:post, Addressable::Template.new("#{client.endpoint}/channels/#{channel_name}/publish{?request_id}")).
+                with do |request|
+                  @request_id = request.uri.query_values['request_id']
+                end.to_return(:status => 200, :body => [], :headers => { 'Content-Type' => 'application/json' })
+            end
+
+            context 'with a single publish' do
+              it 'succeeds and sends the request_id as a param' do
+                channel.publish('name', { body: random_str })
+                expect(@request_id.to_s).to_not be_empty
+              end
+            end
+
+            context 'with an array publish' do
+              it 'succeeds and sends the request_id as a param' do
+                channel.publish([{ body: random_str }, { body: random_str }])
+                expect(@request_id.to_s).to_not be_empty
+              end
+            end
+          end
+
+          context 'without mocks to ensure the requests are accepted' do
+            context 'with a single publish' do
+              it 'succeeds and sends the request_id as a param' do
+                channel.publish('name', { body: random_str })
+                expect(channel.history.items.length).to eql(1)
+              end
+            end
+
+            context 'with an array publish' do
+              it 'succeeds and sends the request_id as a param' do
+                channel.publish([{ body: random_str }, { body: random_str }])
+                expect(channel.history.items.length).to eql(2)
+              end
+            end
+          end
+        end
+
+        context 'option add_request_ids: true and specified fallback hosts', :webmock do
           let(:client_options) { { key: api_key, fallback_hosts_use_default: true, add_request_ids: true } }
           let(:requests)       { [] }
           before do

From 57b9cb7f810231fa42ceccb49ad215131724a25e Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 22:18:08 +0100
Subject: [PATCH 2/9] Ensure the request_id itself is present

Most of the tests were checking that the @request_id param is equal to the request_id in the exception for example.  But at no point are we checking that the request_id itself is valid i.e. it could be `nil` and all the tests would pass.
---
 spec/acceptance/rest/client_spec.rb | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index 29a228985..143362607 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1056,7 +1056,9 @@ def level=(new_level)
             end
           end
           it 'has an error with the same request_id of the request' do
-            expect{ client.time }.to raise_error(Ably::Exceptions::ConnectionTimeout, /#{@request_id}/)
+            expect { client.time }.to raise_error(Ably::Exceptions::ConnectionTimeout, /#{@request_id}/)
+            expect(@request_id).to be_a(String)
+            expect(@request_id).to_not be_empty
             expect(custom_logger_object.logs.find { |severity, message| message.match(/#{@request_id}/i)} ).to_not be_nil
           end
         end
@@ -1124,6 +1126,8 @@ def level=(new_level)
           end
           it 'request_id is the same across retries' do
             expect{ client.time }.to raise_error(Ably::Exceptions::ConnectionTimeout, /#{@request_id}/)
+            expect(@request_id).to be_a(String)
+            expect(@request_id).to_not be_empty
             expect(requests.uniq.count).to eql(1)
             expect(requests.uniq.first).to eql(@request_id)
           end

From 75859b3756b115454acd36dcecf06c82c220ac0c Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 22:18:32 +0100
Subject: [PATCH 3/9] Minor test styling improvements

---
 spec/acceptance/rest/client_spec.rb | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index 143362607..36a497b04 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1017,7 +1017,7 @@ def encode64(text)
 
     context 'request_id generation' do
       context 'Timeout error' do
-        context 'with request_id', :webmock do
+        context 'with option add_request_ids: true', :webmock do
           let(:custom_logger) do
             Class.new do
               def initialize
@@ -1047,6 +1047,7 @@ def level=(new_level)
           end
           let(:custom_logger_object) { custom_logger.new }
           let(:client_options) { default_options.merge(key: api_key, logger: custom_logger_object, add_request_ids: true) }
+
           before do
             @request_id = nil
             stub_request(:get, Addressable::Template.new("#{client.endpoint}/time{?request_id}")).with do |request|
@@ -1055,6 +1056,7 @@ def level=(new_level)
               raise Faraday::TimeoutError.new('timeout error message')
             end
           end
+
           it 'has an error with the same request_id of the request' do
             expect { client.time }.to raise_error(Ably::Exceptions::ConnectionTimeout, /#{@request_id}/)
             expect(@request_id).to be_a(String)
@@ -1063,7 +1065,6 @@ def level=(new_level)
           end
         end
 
-        context 'when specifying fallback hosts', :webmock do
         context 'with option add_request_ids: true and REST operations with a message body' do
           let(:client_options) { default_options.merge({ key: api_key, add_request_ids: true }) }
           let(:channel_name) { random_str }
@@ -1110,8 +1111,9 @@ def level=(new_level)
         end
 
         context 'option add_request_ids: true and specified fallback hosts', :webmock do
-          let(:client_options) { { key: api_key, fallback_hosts_use_default: true, add_request_ids: true } }
+          let(:client_options) { { key: api_key, fallback_hosts_use_default: true, add_request_ids: true, log_level: :error } }
           let(:requests)       { [] }
+
           before do
             @request_id = nil
             hosts = Ably::FALLBACK_HOSTS + ['rest.ably.io']
@@ -1124,7 +1126,8 @@ def level=(new_level)
               end
             end
           end
-          it 'request_id is the same across retries' do
+
+          specify 'request_id is the same across retries' do
             expect{ client.time }.to raise_error(Ably::Exceptions::ConnectionTimeout, /#{@request_id}/)
             expect(@request_id).to be_a(String)
             expect(@request_id).to_not be_empty
@@ -1135,6 +1138,7 @@ def level=(new_level)
 
         context 'without request_id' do
           let(:client_options) { default_options.merge(key: api_key, http_request_timeout: 0) }
+
           it 'does not include request_id in ConnectionTimeout error' do
             begin
               client.stats
@@ -1147,6 +1151,7 @@ def level=(new_level)
 
       context 'UnauthorizedRequest nonce error' do
         let(:token_params) { { nonce: "samenonce_#{protocol}", timestamp:  Time.now.to_i } }
+
         it 'includes request_id in UnauthorizedRequest error due to replayed nonce' do
           client1 = Ably::Rest::Client.new(default_options.merge(key: api_key))
           client2 = Ably::Rest::Client.new(default_options.merge(key: api_key, add_request_ids: true))

From eb3e3f25d1e493f3d79c59124d096efbf4420736 Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 22:18:52 +0100
Subject: [PATCH 4/9] =?UTF-8?q?Don=E2=80=99t=20call=20private=20methods=20?=
 =?UTF-8?q?in=20library=20code?=
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

---
 lib/ably/auth.rb               | 2 +-
 lib/ably/modules/encodeable.rb | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/ably/auth.rb b/lib/ably/auth.rb
index 873e98681..056dce55c 100644
--- a/lib/ably/auth.rb
+++ b/lib/ably/auth.rb
@@ -633,7 +633,7 @@ def token_request_from_auth_url(auth_url, auth_options, token_params)
       method = auth_options[:auth_method] || options[:auth_method] || :get
       params = (auth_options[:auth_params] || options[:auth_method] || {}).merge(token_params)
 
-      response = connection.send(method) do |request|
+      response = connection.public_send(method) do |request|
         request.url uri.path
         request.headers = auth_options[:auth_headers] || {}
         if method.to_s.downcase == 'post'
diff --git a/lib/ably/modules/encodeable.rb b/lib/ably/modules/encodeable.rb
index 08e4ac1ae..3fe6bcd90 100644
--- a/lib/ably/modules/encodeable.rb
+++ b/lib/ably/modules/encodeable.rb
@@ -95,7 +95,7 @@ def apply_encoders(method, encoders, channel_options, &error_callback)
 
         previous_encoding = message_attributes[:encoding]
         encoders.each do |encoder|
-          encoder.send method, message_attributes, channel_options
+          encoder.public_send method, message_attributes, channel_options
         end
       end until previous_encoding == message_attributes[:encoding]
 

From 63fa1c8038ac72e6ec65ddc725dc568db4359c0e Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 22:29:26 +0100
Subject: [PATCH 5/9] DRY up tests with custom logger

---
 spec/acceptance/realtime/auth_spec.rb       | 26 +---------------
 spec/acceptance/rest/auth_spec.rb           | 29 +-----------------
 spec/acceptance/rest/client_spec.rb         | 33 ++++-----------------
 spec/shared/client_initializer_behaviour.rb | 10 +------
 spec/spec_helper.rb                         |  1 +
 spec/support/test_logger_helper.rb          | 24 +++++++++++++++
 spec/unit/logger_spec.rb                    | 10 +------
 7 files changed, 34 insertions(+), 99 deletions(-)
 create mode 100644 spec/support/test_logger_helper.rb

diff --git a/spec/acceptance/realtime/auth_spec.rb b/spec/acceptance/realtime/auth_spec.rb
index 24ee28296..5393643ce 100644
--- a/spec/acceptance/realtime/auth_spec.rb
+++ b/spec/acceptance/realtime/auth_spec.rb
@@ -1016,31 +1016,7 @@ def disconnect_transport(connection)
 
     context 'deprecated #authorise' do
       let(:client_options)  { default_options.merge(key: api_key, logger: custom_logger_object, use_token_auth: true) }
-      let(:custom_logger) do
-        Class.new do
-          def initialize
-            @messages = []
-          end
-
-          [:fatal, :error, :warn, :info, :debug].each do |severity|
-            define_method severity do |message|
-              @messages << [severity, message]
-            end
-          end
-
-          def logs
-            @messages
-          end
-
-          def level
-            1
-          end
-
-          def level=(new_level)
-          end
-        end
-      end
-      let(:custom_logger_object) { custom_logger.new }
+      let(:custom_logger_object) { TestLogger.new }
 
       it 'logs a deprecation warning (#RSA10l)' do
         client.auth.authorise
diff --git a/spec/acceptance/rest/auth_spec.rb b/spec/acceptance/rest/auth_spec.rb
index e8e4a380f..08e4c400c 100644
--- a/spec/acceptance/rest/auth_spec.rb
+++ b/spec/acceptance/rest/auth_spec.rb
@@ -1326,34 +1326,7 @@ def coerce_if_time_value(field_name, value, params = {})
 
     context 'deprecated #authorise' do
       let(:client_options)  { default_options.merge(key: api_key, logger: custom_logger_object, use_token_auth: true) }
-      let(:custom_logger) do
-        Class.new do
-          def initialize
-            @messages = []
-          end
-
-          [:fatal, :error, :warn, :info, :debug].each do |severity|
-            define_method severity do |message, &block|
-              message_val = [message]
-              message_val << block.call if block
-
-              @messages << [severity, message_val.compact.join(' ')]
-            end
-          end
-
-          def logs
-            @messages
-          end
-
-          def level
-            1
-          end
-
-          def level=(new_level)
-          end
-        end
-      end
-      let(:custom_logger_object) { custom_logger.new }
+      let(:custom_logger_object) { TestLogger.new }
 
       it 'logs a deprecation warning (#RSA10l)' do
         client.auth.authorise
diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index 36a497b04..0d2bf1ec4 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1018,34 +1018,7 @@ def encode64(text)
     context 'request_id generation' do
       context 'Timeout error' do
         context 'with option add_request_ids: true', :webmock do
-          let(:custom_logger) do
-            Class.new do
-              def initialize
-                @messages = []
-              end
-
-              [:fatal, :error, :warn, :info, :debug].each do |severity|
-                define_method severity do |message, &block|
-                  message_val = [message]
-                  message_val << block.call if block
-
-                  @messages << [severity, message_val.compact.join(' ')]
-                end
-              end
-
-              def logs
-                @messages
-              end
-
-              def level
-                1
-              end
-
-              def level=(new_level)
-              end
-            end
-          end
-          let(:custom_logger_object) { custom_logger.new }
+          let(:custom_logger_object) { TestLogger.new }
           let(:client_options) { default_options.merge(key: api_key, logger: custom_logger_object, add_request_ids: true) }
 
           before do
@@ -1164,5 +1137,9 @@ def level=(new_level)
         end
       end
     end
+
+    context 'failed request logging' do
+      it 'does not log success'
+    end
   end
 end
diff --git a/spec/shared/client_initializer_behaviour.rb b/spec/shared/client_initializer_behaviour.rb
index aa6f0a5d7..4c9e357e5 100644
--- a/spec/shared/client_initializer_behaviour.rb
+++ b/spec/shared/client_initializer_behaviour.rb
@@ -261,15 +261,7 @@ def rest?
       end
 
       context 'with custom logger and log_level' do
-        let(:custom_logger) do
-          Class.new do
-            extend Forwardable
-            def initialize
-              @logger = Logger.new(STDOUT)
-            end
-            def_delegators :@logger, :fatal, :error, :warn, :info, :debug, :level, :level=
-          end
-        end
+        let(:custom_logger) { TestLogger }
         let(:client_options) { default_options.merge(logger: custom_logger.new, log_level: Logger::DEBUG, auto_connect: false) }
 
         it 'uses the custom logger' do
diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb
index 883925643..63e3f5300 100644
--- a/spec/spec_helper.rb
+++ b/spec/spec_helper.rb
@@ -19,6 +19,7 @@ def console(message)
 require 'support/private_api_formatter'
 require 'support/protocol_helper'
 require 'support/random_helper'
+require 'support/test_logger_helper'
 
 require 'rspec_config'
 
diff --git a/spec/support/test_logger_helper.rb b/spec/support/test_logger_helper.rb
new file mode 100644
index 000000000..bb4540cde
--- /dev/null
+++ b/spec/support/test_logger_helper.rb
@@ -0,0 +1,24 @@
+# Class with standard Ruby Logger interface
+#   but it keeps a record of the lof entries for later inspection
+class TestLogger
+  def initialize
+    @messages = []
+  end
+
+  [:fatal, :error, :warn, :info, :debug].each do |severity|
+    define_method severity do |message|
+      @messages << [severity, message]
+    end
+  end
+
+  def logs
+    @messages
+  end
+
+  def level
+    1
+  end
+
+  def level=(new_level)
+  end
+end
diff --git a/spec/unit/logger_spec.rb b/spec/unit/logger_spec.rb
index c9139ffd7..e124dfded 100644
--- a/spec/unit/logger_spec.rb
+++ b/spec/unit/logger_spec.rb
@@ -121,15 +121,7 @@ def uncolorize(string)
     end
 
     context 'with a valid interface' do
-      let(:custom_logger) do
-        Class.new do
-          extend Forwardable
-          def initialize
-            @logger = Logger.new(STDOUT)
-          end
-          def_delegators :@logger, :fatal, :error, :warn, :info, :debug, :level, :level=
-        end
-      end
+      let(:custom_logger) { TestLogger }
       let(:custom_logger_object) { custom_logger.new }
 
       subject { Ably::Logger.new(rest_client, Logger::INFO, custom_logger_object) }

From 55771a904a73c6331a337d99897afa75310e59a0 Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 23:05:28 +0100
Subject: [PATCH 6/9] Log outcome of REST request retries

Example warnings emitted for a request that fails but then succeeds is now:

```
warn: Ably::Rest::Client - Retry 1 for get /time {} as initial attempt failed (seq #5g-tSQ): getaddrinfo: nodename nor servname provided, or not known (SocketError)
warn: Ably::Rest::Client - Request SUCCEEDED after 1 retry for get /time {} (seq #5g-tSQ, time elapsed 5.11s)
```

And a request that never succeeds:

```
warn: Ably::Rest::Client - Retry 1 for get /time {} as initial attempt failed (seq #KyefoA): getaddrinfo: nodename nor servname provided, or not known (SocketError)
warn: Ably::Rest::Client - Retry 2 for get /time {} as initial attempt failed (seq #KyefoA): getaddrinfo: nodename nor servname provided, or not known (SocketError)
error: Ably::Rest::Client - Request FAILED after 2 retries for get /time {} (seq #KyefoA, time elapsed 15.02s)
```

See related https://github.com/ably/docs/issues/359
---
 lib/ably/rest/client.rb             | 18 ++++++++++++-
 spec/acceptance/rest/client_spec.rb | 40 ++++++++++++++++++++++++++++-
 spec/support/test_logger_helper.rb  | 16 +++++++++---
 3 files changed, 69 insertions(+), 5 deletions(-)

diff --git a/lib/ably/rest/client.rb b/lib/ably/rest/client.rb
index 3289eb18b..4c7e8f6f6 100644
--- a/lib/ably/rest/client.rb
+++ b/lib/ably/rest/client.rb
@@ -439,6 +439,7 @@ def send_request(method, path, params, options)
         max_retry_duration = http_defaults.fetch(:max_retry_duration)
         requested_at       = Time.now
         retry_count        = 0
+        retry_sequence_id  = nil
         request_id         = SecureRandom.urlsafe_base64(10) if add_request_ids
 
         begin
@@ -458,15 +459,30 @@ def send_request(method, path, params, options)
                 end
               end
             end
+          end.tap do
+            if retry_count > 0
+              logger.warn do
+                "Ably::Rest::Client - Request SUCCEEDED after #{retry_count} #{retry_count > 1 ? 'retries' : 'retry' } for" \
+                " #{method} #{path} #{params} (seq ##{retry_sequence_id}, time elapsed #{(Time.now.to_f - requested_at.to_f).round(2)}s)"
+              end
+            end
           end
 
         rescue Faraday::TimeoutError, Faraday::ClientError, Ably::Exceptions::ServerError => error
+          retry_sequence_id ||= SecureRandom.urlsafe_base64(4)
           time_passed = Time.now - requested_at
+
           if can_fallback_to_alternate_ably_host? && retry_count < max_retry_count && time_passed <= max_retry_duration
             retry_count += 1
-            logger.warn { "Ably::Rest::Client - Retry #{retry_count} for #{method} #{path} #{params} as initial attempt failed: #{error}" }
+            logger.warn { "Ably::Rest::Client - Retry #{retry_count} for #{method} #{path} #{params} as initial attempt failed (seq ##{retry_sequence_id}): #{error}" }
             retry
           end
+
+          logger.error do
+            "Ably::Rest::Client - Request FAILED after #{retry_count} #{retry_count > 1 ? 'retries' : 'retry' } for" \
+            " #{method} #{path} #{params} (seq ##{retry_sequence_id}, time elapsed #{(Time.now.to_f - requested_at.to_f).round(2)}s)"
+          end
+
           case error
             when Faraday::TimeoutError
               raise Ably::Exceptions::ConnectionTimeout.new(error.message, nil, 80014, error, { request_id: request_id })
diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index 0d2bf1ec4..e52bef953 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1139,7 +1139,45 @@ def encode64(text)
     end
 
     context 'failed request logging' do
-      it 'does not log success'
+      let(:custom_logger) { TestLogger.new }
+      let(:client_options) { default_options.merge(key: api_key, logger: custom_logger) }
+
+      it 'is absent when requests do not fail' do
+        client.time
+        expect(custom_logger.logs(min_severity: :warn)).to be_empty
+      end
+
+      context 'with the first request failing' do
+        let(:client_options) do
+          default_options.merge(
+            rest_host: 'non.existent.domain.local',
+            fallback_hosts: [[environment, Ably::Rest::Client::DOMAIN].join('-')],
+            key: api_key,
+            logger: custom_logger)
+        end
+
+        it 'is present with success message when requests do not actually fail' do
+          client.time
+          expect(custom_logger.logs(min_severity: :warn).select { |severity, msg| msg.match(/Retry/) }.length).to eql(1)
+          expect(custom_logger.logs(min_severity: :warn).select { |severity, msg| msg.match(/SUCCEEDED/) }.length).to eql(1)
+        end
+      end
+
+      context 'with all requests failing' do
+        let(:client_options) do
+          default_options.merge(
+            rest_host: 'non.existent.domain.local',
+            fallback_hosts: ['non2.existent.domain.local'],
+            key: api_key,
+            logger: custom_logger)
+        end
+
+        it 'is present when all requests fail' do
+          expect { client.time }.to raise_error(Ably::Exceptions::ConnectionError)
+          expect(custom_logger.logs(min_severity: :warn).select { |severity, msg| msg.match(/Retry/) }.length).to eql(2)
+          expect(custom_logger.logs(min_severity: :error).select { |severity, msg| msg.match(/FAILED/) }.length).to eql(1)
+        end
+      end
     end
   end
 end
diff --git a/spec/support/test_logger_helper.rb b/spec/support/test_logger_helper.rb
index bb4540cde..e8d8d307a 100644
--- a/spec/support/test_logger_helper.rb
+++ b/spec/support/test_logger_helper.rb
@@ -5,14 +5,24 @@ def initialize
     @messages = []
   end
 
-  [:fatal, :error, :warn, :info, :debug].each do |severity|
+  SEVERITIES = [:fatal, :error, :warn, :info, :debug]
+  SEVERITIES.each do |severity|
     define_method severity do |message|
       @messages << [severity, message]
     end
   end
 
-  def logs
-    @messages
+  def logs(min_severity: nil)
+    if min_severity
+      severity_level = SEVERITIES.index(min_severity)
+      raise "Unknown severity: #{min_severity}" if severity_level.nil?
+
+      @messages.select do |severity, message|
+        SEVERITIES.index(severity) <= severity_level
+      end
+    else
+      @messages
+    end
   end
 
   def level

From fdbc2b436f0e0745d278610f516bceca7bdc26e1 Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Mon, 30 Apr 2018 23:49:01 +0100
Subject: [PATCH 7/9] Ruby 1.9.* support

---
 spec/support/test_logger_helper.rb | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/spec/support/test_logger_helper.rb b/spec/support/test_logger_helper.rb
index e8d8d307a..7f4b6962e 100644
--- a/spec/support/test_logger_helper.rb
+++ b/spec/support/test_logger_helper.rb
@@ -12,7 +12,8 @@ def initialize
     end
   end
 
-  def logs(min_severity: nil)
+  def logs(options = {})
+    min_severity = options[:min_severity]
     if min_severity
       severity_level = SEVERITIES.index(min_severity)
       raise "Unknown severity: #{min_severity}" if severity_level.nil?

From a81891b86792d315a5b215e19aa919bd34bdbddf Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Tue, 1 May 2018 00:06:36 +0100
Subject: [PATCH 8/9] tests: Avoid stubbing of logger when testing the logger,
 improve logger

Mixing the test debug failure logger and this new logger is causing unreliable tests when using the new test logger.
This implementation is complete with support for blocks and the other logger is now disabled for these tests.
---
 spec/acceptance/realtime/auth_spec.rb |  2 +-
 spec/acceptance/rest/auth_spec.rb     |  2 +-
 spec/acceptance/rest/client_spec.rb   |  4 ++--
 spec/support/test_logger_helper.rb    | 13 ++++++++++---
 4 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/spec/acceptance/realtime/auth_spec.rb b/spec/acceptance/realtime/auth_spec.rb
index 5393643ce..9e2312682 100644
--- a/spec/acceptance/realtime/auth_spec.rb
+++ b/spec/acceptance/realtime/auth_spec.rb
@@ -1014,7 +1014,7 @@ def disconnect_transport(connection)
       end
     end
 
-    context 'deprecated #authorise' do
+    context 'deprecated #authorise', :prevent_log_stubbing do
       let(:client_options)  { default_options.merge(key: api_key, logger: custom_logger_object, use_token_auth: true) }
       let(:custom_logger_object) { TestLogger.new }
 
diff --git a/spec/acceptance/rest/auth_spec.rb b/spec/acceptance/rest/auth_spec.rb
index 08e4c400c..1567500e2 100644
--- a/spec/acceptance/rest/auth_spec.rb
+++ b/spec/acceptance/rest/auth_spec.rb
@@ -1324,7 +1324,7 @@ def coerce_if_time_value(field_name, value, params = {})
       end
     end
 
-    context 'deprecated #authorise' do
+    context 'deprecated #authorise', :prevent_log_stubbing do
       let(:client_options)  { default_options.merge(key: api_key, logger: custom_logger_object, use_token_auth: true) }
       let(:custom_logger_object) { TestLogger.new }
 
diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index e52bef953..2ffa42b47 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1017,7 +1017,7 @@ def encode64(text)
 
     context 'request_id generation' do
       context 'Timeout error' do
-        context 'with option add_request_ids: true', :webmock do
+        context 'with option add_request_ids: true', :webmock, :prevent_log_stubbing do
           let(:custom_logger_object) { TestLogger.new }
           let(:client_options) { default_options.merge(key: api_key, logger: custom_logger_object, add_request_ids: true) }
 
@@ -1138,7 +1138,7 @@ def encode64(text)
       end
     end
 
-    context 'failed request logging' do
+    context 'failed request logging', :prevent_log_stubbing do
       let(:custom_logger) { TestLogger.new }
       let(:client_options) { default_options.merge(key: api_key, logger: custom_logger) }
 
diff --git a/spec/support/test_logger_helper.rb b/spec/support/test_logger_helper.rb
index 7f4b6962e..4242cb133 100644
--- a/spec/support/test_logger_helper.rb
+++ b/spec/support/test_logger_helper.rb
@@ -1,14 +1,21 @@
 # Class with standard Ruby Logger interface
 #   but it keeps a record of the lof entries for later inspection
+#
+# Recommendation: Use :prevent_log_stubbing attibute on tests that use this logger
+#
 class TestLogger
   def initialize
     @messages = []
   end
 
   SEVERITIES = [:fatal, :error, :warn, :info, :debug]
-  SEVERITIES.each do |severity|
-    define_method severity do |message|
-      @messages << [severity, message]
+  SEVERITIES.each do |severity_sym|
+    define_method(severity_sym) do |*args, &block|
+      if block
+        @messages << [severity_sym, block.call]
+      else
+        @messages << [severity_sym, args.join(', ')]
+      end
     end
   end
 

From 58d0bf0e9332cd6e07d7e4305bb552104766df4b Mon Sep 17 00:00:00 2001
From: Matthew O'Riordan <matthew.oriordan@gmail.com>
Date: Tue, 1 May 2018 01:00:58 +0100
Subject: [PATCH 9/9] Improve test reliability

We can get more than 2 warnings, but we will have at least two
---
 spec/acceptance/rest/client_spec.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/spec/acceptance/rest/client_spec.rb b/spec/acceptance/rest/client_spec.rb
index 2ffa42b47..9dd5e9fc7 100644
--- a/spec/acceptance/rest/client_spec.rb
+++ b/spec/acceptance/rest/client_spec.rb
@@ -1174,7 +1174,7 @@ def encode64(text)
 
         it 'is present when all requests fail' do
           expect { client.time }.to raise_error(Ably::Exceptions::ConnectionError)
-          expect(custom_logger.logs(min_severity: :warn).select { |severity, msg| msg.match(/Retry/) }.length).to eql(2)
+          expect(custom_logger.logs(min_severity: :warn).select { |severity, msg| msg.match(/Retry/) }.length).to be >= 2
           expect(custom_logger.logs(min_severity: :error).select { |severity, msg| msg.match(/FAILED/) }.length).to eql(1)
         end
       end