diff --git a/debian/changelog b/debian/changelog index a1bf2ff..8d6029f 100644 --- a/debian/changelog +++ b/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 Thu, 11 Jan 2018 10:05:35 +0000 diff --git a/tests/acceptance/ld_preload.rb b/tests/acceptance/ld_preload.rb new file mode 100644 index 0000000..405660e --- /dev/null +++ b/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 diff --git a/tests/acceptance/ld_preloads/msync_catcher.c b/tests/acceptance/ld_preloads/msync_logger.c similarity index 94% rename from tests/acceptance/ld_preloads/msync_catcher.c rename to tests/acceptance/ld_preloads/msync_logger.c index 18ef284..73543cd 100644 --- a/tests/acceptance/ld_preloads/msync_catcher.c +++ b/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); diff --git a/tests/acceptance/ld_preloads/setsockopt_logger.c b/tests/acceptance/ld_preloads/setsockopt_logger.c new file mode 100644 index 0000000..d2cc021 --- /dev/null +++ b/tests/acceptance/ld_preloads/setsockopt_logger.c @@ -0,0 +1,38 @@ +#define _GNU_SOURCE + +#include +#include +#include +#include + +/* + * 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; +} diff --git a/tests/acceptance/proxy_tests.rb b/tests/acceptance/proxy_tests.rb index 897c487..afd7a11 100644 --- a/tests/acceptance/proxy_tests.rb +++ b/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,45 +151,58 @@ module ProxyTests def test_write_request_retried_when_upstream_dies_partway maker = make_fake_server - with_proxied_client(4096) do |client| - server, sc1 = maker.value + with_ld_preload('setsockopt_logger') do + with_proxied_client(4096) do |client| + server, sc1 = maker.value - # Send the read request to the proxy - client.write(0, (b * 4096)) + # Send the read request to the proxy + client.write(0, (b * 4096)) - # ensure we're given the read request - req1 = sc1.read_request - assert_equal ::FlexNBD::REQUEST_MAGIC, req1[:magic] - assert_equal ::FlexNBD::REQUEST_WRITE, req1[:type] - assert_equal 0, req1[:from] - assert_equal 4096, req1[:len] - data1 = sc1.read_data(4096) - assert_equal((b * 4096), data1, 'Data not proxied successfully') + # ensure we're given the read request + req1 = sc1.read_request + assert_equal ::FlexNBD::REQUEST_MAGIC, req1[:magic] + assert_equal ::FlexNBD::REQUEST_WRITE, req1[:type] + assert_equal 0, req1[:from] + assert_equal 4096, req1[:len] + data1 = sc1.read_data(4096) + assert_equal((b * 4096), data1, 'Data not proxied successfully') - # Kill the server again, now we're sure the read request has been sent once - sc1.close + # Read the setsockopt logs, so we can check that TCP_NODELAY is re-set + # later + read_ld_preload_log('setsockopt_logger') - # We expect the proxy to reconnect without our client doing anything. - sc2 = server.accept - sc2.write_hello + # Kill the server again, now we're sure the read request has been sent once + sc1.close - # And once reconnected, it should resend an identical request. - req2 = sc2.read_request - assert_equal req1, req2 - data2 = sc2.read_data(4096) - assert_equal data1, data2 + # We expect the proxy to reconnect without our client doing anything. + sc2 = server.accept + sc2.write_hello - # The reply should be proxied back to the client. - sc2.write_reply(req2[:handle]) + # And once reconnected, it should resend an identical request. + req2 = sc2.read_request + assert_equal req1, req2 + data2 = sc2.read_data(4096) + assert_equal data1, data2 - # Check it to make sure it's correct - rsp = Timeout.timeout(15) { client.read_response } - assert_equal ::FlexNBD::REPLY_MAGIC, rsp[:magic] - assert_equal 0, rsp[:error] - assert_equal req1[:handle], rsp[:handle] + # The reply should be proxied back to the client. + sc2.write_reply(req2[:handle]) - sc2.close - server.close + # Check it to make sure it's correct + rsp = Timeout.timeout(15) { client.read_response } + assert_equal ::FlexNBD::REPLY_MAGIC, rsp[:magic] + assert_equal 0, rsp[:error] + assert_equal req1[:handle], rsp[:handle] + + 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 diff --git a/tests/acceptance/test_serve_mode.rb b/tests/acceptance/test_serve_mode.rb index 2299584..6c3e3f6 100644 --- a/tests/acceptance/test_serve_mode.rb +++ b/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,39 +132,42 @@ class TestServeMode < Test::Unit::TestCase end def test_flush_is_accepted - setup_msync_catcher - connect_to_server do |client| - client.flush - rsp = client.read_response - assert_equal FlexNBD::REPLY_MAGIC, rsp[:magic] - assert_equal 0, rsp[:error] + 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_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 - op = parse_msync_output - 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 def test_write_with_fua_is_accepted - setup_msync_catcher - page_size = Integer(`getconf PAGESIZE`) - @env.blocksize = page_size * 10 - connect_to_server do |client| - # Write somewhere in the third page - pos = page_size * 3 + 100 - client.write_with_fua(pos, "\x00" * 33) - rsp = client.read_response - assert_equal FlexNBD::REPLY_MAGIC, rsp[:magic] - assert_equal 0, rsp[:error] + 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 + pos = page_size * 3 + 100 + client.write_with_fua(pos, "\x00" * 33) + rsp = client.read_response + assert_equal FlexNBD::REPLY_MAGIC, rsp[:magic] + assert_equal 0, rsp[:error] + end + op = parse_ld_preload_logs('msync_logger') + + assert_equal 1, op.count, 'Only one msync expected' + + # Should be 100 + 33, as we've started writing 100 bytes into a page, for + # 33 bytes + assert_equal 133, op.first[2], 'msync length wrong' + assert_equal 6, op.first[3], 'msync called with incorrect flags' end - - 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 - # 33 bytes - assert_equal 133, op.first[2], 'msync length wrong' - assert_equal 6, op.first[3], 'msync called with incorrect flags' end def test_odd_size_discs_are_truncated_to_nearest_512 @@ -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