Added logging to resolver to assist debugging travis issues.

Author: ioquatix

lib/rubydns/resolver.rb

@@ -69,20 +69,25 @@ def initialize(message, servers, options = {}, &block)
 
 # Measured in seconds:
 @timeout = options[:timeout] || 5
+
+@logger = options[:logger]
 end
 
 attr :message
 attr :packet
+attr :logger
 
 def run!
 try_next_server!
 end
 
 def process_response!(response)
 if response.tc != 0
+@logger.warn "[#{@message.id}] Received truncated response!" if @logger
 # We hardcode this behaviour for now.
 try_next_server!
 else
+@logger.warn "[#{@message.id}] Received valid response #{response.inspect}" if @logger
 succeed response
 end
 end
@@ -98,6 +103,8 @@ def try_next_server!
 if @servers.size > 0
 @server = @servers.shift
 
+@logger.debug "[#{@message.id}] Sending request to server #{@server.inspect}" if @logger
+
 # We make requests one at a time to the given server, naturally the servers are ordered in terms of priority.
 case @server[0]
 when :udp
@@ -110,6 +117,8 @@ def try_next_server!
 
 # Setting up the timeout...
 EventMachine::Timer.new(@timeout) do
+@logger.debug "[#{@message.id}] Request timed out!" if @logger
+
 try_next_server!
 end
 else
@@ -141,6 +150,8 @@ def receive_data(data)
 # The message id must match, and it can't be truncated:
 if message.id == @request.message.id
 @request.process_response!(message)
+else
+@request.logger.warn "[#{@request.message.id}] Received response with incorrect message id: #{message.id}" if @request.logger
 end
 end
 end
@@ -181,6 +192,8 @@ def receive_data(data)
 
 if message.id == @request.message.id
 @request.process_response!(message)
+else
+@request.logger.warn "[#{@request.message.id}] Received response with incorrect message id: #{message.id}" if @request.logger
 end
 elsif @buffer.size > (@length + 2)
 @request.try_next_server!

lib/rubydns/server.rb

@@ -175,21 +175,21 @@ def process_query(query, &block)
 
 # 4/ Finally, the answer is given back to the calling block:
 chain << lambda do
+@logger.debug "Passing answer back to caller..."
 yield answer
 end
 
 # There may be multiple questions per query
 query.question.reverse.each do |question, resource_class|
 next_link = chain.last
-
+
 chain << lambda do
 @logger.debug "Processing question #{question} #{resource_class}..."
 
 transaction = Transaction.new(self, query, question, resource_class, answer)
 
 # Call the next link in the chain:
 transaction.callback do
-@logger.warn "Calling next link..."
 # 3/ ... which calls the previous item in the chain, i.e. the next question to be answered:
 next_link.call
 end

test/test_truncation.rb

@@ -30,6 +30,7 @@ def self.run
 class TruncationTest < Test::Unit::TestCase
 def setup
 TruncatedServer.start
+TruncatedServer.status
 end
 
 def teardown
@@ -38,10 +39,13 @@ def teardown
 end
 
 def test_tcp_failover
-resolver = RubyDNS::Resolver.new([[:udp, '127.0.0.1', 5320], [:tcp, '127.0.0.1', 5320]])
+logger = Logger.new($stderr)
+resolver = RubyDNS::Resolver.new([[:udp, '127.0.0.1', 5320], [:tcp, '127.0.0.1', 5320]], :logger => logger)
 
 EventMachine::run do
 resolver.query("truncation", IN::TXT) do |response|
+
+
 text = response.answer.first
 
 assert_equal "Hello World! " * 100, text[2].strings.join