Merge branch 'rationalise-ld-preload-tests' into develop

debian/changelog

@@ -18,6 +18,8 @@ flexnbd (0.2.0) UNRELEASED; urgency=medium
   * Tweak logging for readloop failures (!44)
   * Alter semantics of NBD_MAX_BLOCK_SIZE to remove struct size overheads when
     calculating if a request exceeds the max block size (!45)
+  * Added tests for setting TCP_NODELAY on upstream-reconnections in the
+    proxy, and refactored the other LD_PRELOAD tests (!43)
 
  -- James Carter <james.carter@bytemark.co.uk>  Thu, 11 Jan 2018 10:05:35 +0000
 

tests/acceptance/ld_preload.rb

@@ -0,0 +1,55 @@
+require 'tempfile'
+
+#
+# LdPreload is a little wrapper for using LD_PRELOAD loggers to pick up system
+# calls when testing flexnbd.
+#
+module LdPreload
+  #
+  # This takes an object name, sets up a temporary log file, whose name is
+  # recorded in the environment as OUTPUT_obj_name, where obj_name is the
+  # name of the preload module to build and load.
+  def with_ld_preload(obj_name)
+    @ld_preload_logs ||= {}
+    flunk 'Can only load a preload module once!' if @ld_preload_logs[obj_name]
+
+    system("make -C ld_preloads/ #{obj_name}.o > /dev/null") ||
+      flunk("Failed to build object #{obj_name}")
+    orig_env = ENV['LD_PRELOAD']
+    ENV['LD_PRELOAD'] = [orig_env, File.expand_path("./ld_preloads/#{obj_name}.o")].compact.join(' ')
+
+    # Open the log, and stick it in a hash
+    @ld_preload_logs[obj_name] = Tempfile.new(obj_name)
+    ENV['OUTPUT_' + obj_name] = @ld_preload_logs[obj_name].path
+
+    yield
+  ensure
+    if @ld_preload_logs[obj_name]
+      @ld_preload_logs[obj_name].close
+      @ld_preload_logs.delete(obj_name)
+    end
+    ENV['LD_PRELOAD'] = orig_env
+  end
+
+  def read_ld_preload_log(obj_name)
+    lines = []
+    lines << @ld_preload_logs[obj_name].readline.chomp until
+      @ld_preload_logs[obj_name].eof?
+    lines
+  end
+
+  #
+  # The next to methods assume the log file has one entry per line, and that
+  # each entry is a series of values separated by colons.
+  #
+  def parse_ld_preload_logs(obj_name)
+    read_ld_preload_log(obj_name).map do |l|
+      l.split(':').map { |i| i =~ /^\d+$/ ? i.to_i : i }
+    end
+  end
+
+  def assert_func_call(loglines, args, msg)
+    re = Regexp.new('^' + args.join(':'))
+    assert(loglines.any? { |l| l.match(re) }, msg)
+  end
+end

tests/acceptance/ld_preloads/msync_logger.c

@@ -22,7 +22,7 @@ int msync(void *addr, size_t length, int flags) {
   
   retval = real_msync(addr, length, flags);
   
-  fn = getenv("MSYNC_CATCHER_OUTPUT");
+  fn = getenv("OUTPUT_msync_logger");
   if ( fn != NULL ) {
     fd = fopen(fn,"a");
     fprintf(fd,"msync:%d:%i:%i:%i\n", addr, length, flags, retval);

tests/acceptance/ld_preloads/setsockopt_logger.c

@@ -0,0 +1,38 @@
+#define _GNU_SOURCE
+
+#include <dlfcn.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <sys/socket.h>
+
+/*
+ * Noddy LD_PRELOAD wrapper to catch setsockopt calls, and log them to a file.
+ */
+
+typedef int (*real_setsockopt_t)(int sockfd, int level, int optname, const void *optval, socklen_t optlen);
+
+int real_setsockopt(int sockfd, int level, int optname, const void *optval, socklen_t optlen)
+{
+  return ((real_setsockopt_t)dlsym(RTLD_NEXT, "setsockopt"))(sockfd, level, optname, optval, optlen);
+}
+
+int setsockopt(int sockfd, int level, int optname, const void *optval, socklen_t optlen)
+{
+  FILE *fd;
+  char *fn;
+  int retval;
+  
+  retval = real_setsockopt(sockfd, level, optname, optval, optlen);
+  fn = getenv("OUTPUT_setsockopt_logger");
+
+  /* 
+   * Only interested in catching non-null 4-byte (integer) values 
+   */
+  if ( fn != NULL && optval != NULL && optlen == 4) {
+    fd = fopen(fn,"a");
+    fprintf(fd,"setsockopt:%i:%i:%i:%i:%i\n", sockfd, level, optname, *(int *)optval, retval);
+    fclose(fd);
+  }
+
+  return retval;
+}

tests/acceptance/proxy_tests.rb

@@ -1,8 +1,12 @@
 
 require 'flexnbd/fake_source'
 require 'flexnbd/fake_dest'
+require 'ld_preload'
 
 module ProxyTests
+
+  include LdPreload
+
   def b
     "\xFF".b
   end
@@ -147,6 +151,7 @@ module ProxyTests
   def test_write_request_retried_when_upstream_dies_partway
     maker = make_fake_server
 
+    with_ld_preload('setsockopt_logger') do
       with_proxied_client(4096) do |client|
         server, sc1 = maker.value
 
@@ -162,6 +167,10 @@ module ProxyTests
         data1 = sc1.read_data(4096)
         assert_equal((b * 4096), data1, 'Data not proxied successfully')
 
+        # Read the setsockopt logs, so we can check that TCP_NODELAY is re-set
+        # later
+        read_ld_preload_log('setsockopt_logger')
+
         # Kill the server again, now we're sure the read request has been sent once
         sc1.close
 
@@ -186,6 +195,14 @@ module ProxyTests
 
         sc2.close
         server.close
+
+        # Check TCP_NODELAY was set on the upstream socket
+        log = read_ld_preload_log('setsockopt_logger')
+        assert_func_call(log,
+                         ['setsockopt', 3,
+                          Socket::SOL_TCP, Socket::TCP_NODELAY, 1, 0],
+                         'TCP_NODELAY not set on upstream fd 3')
+      end
     end
   end
 

tests/acceptance/test_serve_mode.rb

@@ -1,9 +1,11 @@
 require 'test/unit'
 require 'environment'
 require 'flexnbd/fake_source'
-require 'tempfile'
+require 'ld_preload'
 
 class TestServeMode < Test::Unit::TestCase
+  include LdPreload
+
   def setup
     super
     @b = "\xFF".b
@@ -12,7 +14,6 @@ class TestServeMode < Test::Unit::TestCase
 
   def teardown
     @env.cleanup
-    teardown_msync_catcher
     super
   end
 
@@ -39,35 +40,6 @@ class TestServeMode < Test::Unit::TestCase
     end
   end
 
-  def setup_msync_catcher
-    `make -C ld_preloads/ msync_catcher.o`
-    omit 'LD_PRELOAD library not found' unless
-      File.exist?('ld_preloads/msync_catcher.o')
-
-    @msync_catcher = Tempfile.new('msync')
-    ENV['MSYNC_CATCHER_OUTPUT'] = @msync_catcher.path
-
-    @ld_preload_orig = ENV['LD_PRELOAD']
-    ENV['LD_PRELOAD'] = 'ld_preloads/msync_catcher.o'
-  end
-
-  def parse_msync_output
-    op = []
-    until @msync_catcher.eof?
-      op << @msync_catcher.readline.chomp.split(':').map do |e|
-        e =~ /^\d+$/ ? e.to_i : e
-      end
-    end
-    op
-  end
-
-  def teardown_msync_catcher
-    @msync_catcher.close if @msync_catcher
-
-    ENV.delete 'MSYNC_CATCHER_OUTPUT'
-    ENV['LD_PRELOAD'] = @ld_preload_orig
-  end
-
   def test_bad_request_magic_receives_error_response
     connect_to_server do |client|
       # replace REQUEST_MAGIC with all 0s to make it look bad
@@ -160,22 +132,24 @@ class TestServeMode < Test::Unit::TestCase
   end
 
   def test_flush_is_accepted
-    setup_msync_catcher
+    with_ld_preload('msync_logger') do
       connect_to_server do |client|
         client.flush
         rsp = client.read_response
         assert_equal FlexNBD::REPLY_MAGIC, rsp[:magic]
         assert_equal 0, rsp[:error]
       end
-    op = parse_msync_output
+      op = parse_ld_preload_logs('msync_logger')
       assert_equal 1, op.count, 'Only one msync expected'
       assert_equal @env.blocksize, op.first[2], 'msync length wrong'
       assert_equal 6, op.first[3], 'msync called with incorrect flags'
     end
+  end
 
   def test_write_with_fua_is_accepted
-    setup_msync_catcher
+    with_ld_preload('msync_logger') do
       page_size = Integer(`getconf PAGESIZE`)
+
       @env.blocksize = page_size * 10
       connect_to_server do |client|
         # Write somewhere in the third page
@@ -185,8 +159,8 @@ class TestServeMode < Test::Unit::TestCase
         assert_equal FlexNBD::REPLY_MAGIC, rsp[:magic]
         assert_equal 0, rsp[:error]
       end
+      op = parse_ld_preload_logs('msync_logger')
 
-    op = parse_msync_output
       assert_equal 1, op.count, 'Only one msync expected'
 
       # Should be 100 + 33, as we've started writing 100 bytes into a page, for
@@ -194,6 +168,7 @@ class TestServeMode < Test::Unit::TestCase
       assert_equal 133, op.first[2], 'msync length wrong'
       assert_equal 6, op.first[3], 'msync called with incorrect flags'
     end
+  end
 
   def test_odd_size_discs_are_truncated_to_nearest_512
     # This should get rounded down to 1024
@@ -209,4 +184,27 @@ class TestServeMode < Test::Unit::TestCase
       client.close
     end
   end
+
+  def test_server_sets_tcpkeepalive
+    with_ld_preload('setsockopt_logger') do
+      connect_to_server(&:close)
+      op = read_ld_preload_log('setsockopt_logger')
+      assert_func_call(op,
+                       ['setsockopt', '\d+',
+                        Socket::SOL_SOCKET, Socket::SO_KEEPALIVE, 1, 0],
+                       'TCP Keepalive not successfully set')
+      assert_func_call(op,
+                       ['setsockopt', '\d+',
+                        Socket::SOL_TCP, Socket::TCP_KEEPIDLE, 30, 0],
+                       'TCP Keepalive idle timeout not set to 30s')
+      assert_func_call(op,
+                       ['setsockopt', '\d+',
+                        Socket::SOL_TCP, Socket::TCP_KEEPINTVL, 10, 0],
+                       'TCP keepalive retry time not set to 10s')
+      assert_func_call(op,
+                       ['setsockopt', '\d+',
+                        Socket::SOL_TCP, Socket::TCP_KEEPCNT, 3, 0],
+                       'TCP keepalive count not set to 3')
+    end
+  end
 end