git.gag.com Git - debian/amanda/blob - installcheck/taper.pl

   1 # Copyright (c) 2009, 2010 Zmanda, Inc.  All Rights Reserved.
   2 #
   3 # This program is free software; you can redistribute it and/or modify it
   4 # under the terms of the GNU General Public License version 2 as published
   5 # by the Free Software Foundation.
   6 #
   7 # This program is distributed in the hope that it will be useful, but
   8 # WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
   9 # or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  10 # for more details.
  11 #
  12 # You should have received a copy of the GNU General Public License along
  13 # with this program; if not, write to the Free Software Foundation, Inc.,
  14 # 59 Temple Place, Suite 330, Boston, MA  02111-1307 USA
  15 #
  16 # Contact information: Zmanda Inc, 465 S. Mathilda Ave., Suite 300
  17 # Sunnyvale, CA 94086, USA, or: http://www.zmanda.com
  18
  19 use Test::More tests => 201;
  20 use strict;
  21 use warnings;
  22
  23 use lib '@amperldir@';
  24 use Installcheck::Run;
  25 use Installcheck::Mock;
  26 use IO::Handle;
  27 use IPC::Open3;
  28 use Data::Dumper;
  29 use IO::Socket::INET;
  30 use POSIX ":sys_wait_h";
  31 use Cwd qw(abs_path);
  32
  33 use Amanda::Paths;
  34 use Amanda::Header qw( :constants );
  35 use Amanda::Debug;
  36 use Amanda::Paths;
  37 use Amanda::Device qw( :constants );
  38
  39 # ABOUT THESE TESTS:
  40 #
  41 # We run a sequence of fixed interactions with the taper, putting it
  42 # through its paces.  Each message to or from the taper is represented
  43 # as a test, for readability.  If the taper produces unexpected results,
  44 # the script dies, on the assumption that subsequent tests will be
  45 # meaningless.
  46 #
  47 # This uses IPC::Open3 instead of Expect mainly because the interactions
  48 # are so carefully scripted that Expect is not required.
  49
  50 # put the debug messages somewhere
  51 Amanda::Debug::dbopen("installcheck");
  52 Installcheck::log_test_output();
  53
  54 my $test_filename = "$Installcheck::TMP/installcheck-taper-holding-file";
  55 my $taper_stderr_file = "$Installcheck::TMP/taper-stderr";
  56 my $debug = !exists $ENV{'HARNESS_ACTIVE'};
  57
  58 # information on the current run
  59 my ($datestamp, $handle);
  60 my ($taper_pid, $taper_in, $taper_out, $last_taper_reply, $taper_reply_timeout);
  61
  62 sub run_taper {
  63     my ($length, $description, %params) = @_;
  64
  65     cleanup_taper();
  66
  67     unless ($params{'keep_config'}) {
  68         my $testconf;
  69         if ($params{'new_vtapes'}) {
  70             $testconf = Installcheck::Run::setup(1);
  71         } else {
  72             $testconf = Installcheck::Run::setup();
  73         }
  74         $testconf->add_param('autolabel', '"TESTCONF%%" empty volume_error');
  75         if ($params{'notapedev'}) {
  76             $testconf->remove_param('tapedev');
  77             $testconf->remove_param('tpchanger');
  78         } elsif ($params{'ndmp_server'}) {
  79             my $ndmp = $params{'ndmp_server'};
  80             $ndmp->reset();
  81             $ndmp->config($testconf);
  82         }
  83         unless ($params{'leom'} or $params{'ndmp_server'}) {
  84             $testconf->add_param('device_property', '"LEOM" "OFF"');
  85         }
  86         $testconf->add_param('debug_taper', '9'); ## TEMPORARY
  87         $testconf->add_tapetype('TEST-TAPE', [
  88             'length' =>  "$length",
  89             ]);
  90         $testconf->write();
  91     }
  92
  93     open(TAPER_ERR, ">", $taper_stderr_file);
  94     $taper_in = $taper_out = '';
  95     $taper_pid = open3($taper_in, $taper_out, ">&TAPER_ERR",
  96         "$amlibexecdir/taper", "TESTCONF");
  97     close TAPER_ERR;
  98     $taper_in->blocking(1);
  99     $taper_out->autoflush();
 100
 101     if ($params{'keep_config'}) {
 102         pass("spawned new taper for $description (same config)");
 103     } else {
 104         pass("spawned taper for $description (tape length $length kb)");
 105     }
 106
 107     # define this to get the installcheck to wait and allow you to attach
 108     # a gdb instance to the taper
 109     if ($params{'use_gdb'}) {
 110         $taper_reply_timeout = 0; # no timeouts while debugging
 111         diag("attach debugger to pid $taper_pid and press ENTER");
 112         <>;
 113     } else {
 114         $taper_reply_timeout = 120;
 115     }
 116
 117     taper_cmd("START-TAPER worker0 $datestamp");
 118 }
 119
 120 sub wait_for_exit {
 121     if ($taper_pid) {
 122         waitpid($taper_pid, 0);
 123         $taper_pid = undef;
 124     }
 125 }
 126
 127 sub cleanup_taper {
 128     -f $test_filename and unlink($test_filename);
 129     -f $taper_stderr_file and unlink($taper_stderr_file);
 130
 131     # make a small effort to collect zombies
 132     if ($taper_pid) {
 133         if (waitpid($taper_pid, WNOHANG) == $taper_pid) {
 134             $taper_pid = undef;
 135         }
 136     }
 137 }
 138
 139 sub taper_cmd {
 140     my ($cmd) = @_;
 141
 142     diag(">>> $cmd") if $debug;
 143     print $taper_in "$cmd\n";
 144 }
 145
 146 sub taper_reply {
 147     local $SIG{ALRM} = sub { die "Timeout while waiting for reply\n" };
 148     alarm($taper_reply_timeout);
 149     $last_taper_reply = $taper_out->getline();
 150     alarm(0);
 151
 152     if (!$last_taper_reply) {
 153         die("wrong pid") unless ($taper_pid == waitpid($taper_pid, 0));
 154         my $exit_status = $?;
 155
 156         open(my $fh, "<", $taper_stderr_file) or die("open $taper_stderr_file: $!");
 157         my $stderr = do { local $/; <$fh> };
 158         close($fh);
 159
 160         diag("taper stderr:\n$stderr") if $stderr;
 161         die("taper (pid $taper_pid) died unexpectedly with status $exit_status");
 162     }
 163
 164     # trim trailing whitespace -- C taper outputs an extra ' ' after
 165     # single-word replies
 166     $last_taper_reply =~ s/\s*$//;
 167     diag("<<< $last_taper_reply") if $debug;
 168
 169     return $last_taper_reply;
 170 }
 171
 172 sub check_logs {
 173     my ($expected, $msg) = @_;
 174     my $re;
 175     my $line;
 176
 177     # must contain a pid line at the beginning and end
 178     unshift @$expected, qr/^INFO taper taper pid \d+$/;
 179     push @$expected, qr/^INFO taper pid-done \d+$/;
 180
 181     open(my $logfile, "<", "$CONFIG_DIR/TESTCONF/log/log")
 182         or die("opening log: $!");
 183     my @logfile = grep(/^\S+ taper /, <$logfile>);
 184     close($logfile);
 185
 186     while (@logfile and @$expected) {
 187         my $logline = shift @logfile;
 188         my $expline = shift @$expected;
 189         chomp $logline;
 190         if ($logline !~ $expline) {
 191             like($logline, $expline, $msg);
 192             return;
 193         }
 194     }
 195     if (@logfile) {
 196         fail("$msg (extra trailing log lines)");
 197         return;
 198     }
 199     if (@$expected) {
 200         fail("$msg (logfile ends early)");
 201         diag("first missing line should match ");
 202         diag("".$expected->[0]);
 203         return;
 204     }
 205
 206     pass($msg);
 207 }
 208
 209 sub cleanup_log {
 210     my $logfile = "$CONFIG_DIR/TESTCONF/log/log";
 211     -f $logfile and unlink($logfile);
 212 }
 213
 214 # functions to create dumpfiles
 215
 216 sub write_dumpfile_header_to {
 217     my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
 218
 219     my $hdr = Amanda::Header->new();
 220     $hdr->{'type'} = $Amanda::Header::F_DUMPFILE;
 221     $hdr->{'datestamp'} = $datestamp;
 222     $hdr->{'dumplevel'} = 0;
 223     $hdr->{'compressed'} = 0;
 224     $hdr->{'comp_suffix'} = ".foo";
 225     $hdr->{'name'} = $hostname;
 226     $hdr->{'disk'} = $disk;
 227     $hdr->{'program'} = "INSTALLCHECK";
 228     $hdr = $hdr->to_string(32768,32768);
 229
 230     $fh->syswrite($hdr, 32768);
 231 }
 232
 233 sub write_dumpfile_data_to {
 234     my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
 235
 236     my $bytes_to_write = $size;
 237     my $bufbase = substr((('='x127)."\n".('-'x127)."\n") x 4, 8, -3) . "1K\n";
 238     die length($bufbase) unless length($bufbase) == 1024-8;
 239     my $k = 0;
 240     while ($bytes_to_write > 0) {
 241         my $buf = sprintf("%08x", $k++).$bufbase;
 242         my $written = $fh->syswrite($buf, $bytes_to_write);
 243         if (!defined($written)) {
 244             die "writing: $!" unless $expect_failure;
 245             exit;
 246         }
 247         $bytes_to_write -= $written;
 248     }
 249 }
 250
 251 # make a new holding-like file in test_filename
 252 sub make_holding_file {
 253     my ($size, $hostname, $disk) = @_;
 254     open(my $fh, ">", $test_filename);
 255     write_dumpfile_header_to($fh, $size, $hostname, $disk);
 256     write_dumpfile_data_to($fh, $size, $hostname, $disk);
 257 }
 258
 259 # connect to the given port and write a dumpfile; this *will* create
 260 # zombies, but it's OK -- installchecks aren't daemons.
 261 sub write_to_port {
 262     my ($port_cmd, $size, $hostname, $disk, $expect_error) = @_;
 263
 264     my ($header_port, $data_addr) =
 265         ($last_taper_reply =~ /^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+)/);
 266
 267     # just run this in the child
 268     return unless fork() == 0;
 269
 270     my $sock = IO::Socket::INET->new(
 271         PeerAddr => "127.0.0.1:$header_port",
 272         Proto => "tcp",
 273         ReuseAddr => 1,
 274     );
 275
 276     write_dumpfile_header_to($sock, $size, $hostname, $disk, $expect_error);
 277     close $sock;
 278
 279     $sock = IO::Socket::INET->new(
 280         PeerAddr => $data_addr,
 281         Proto => "tcp",
 282         ReuseAddr => 1,
 283     );
 284
 285     write_dumpfile_data_to($sock, $size, $hostname, $disk, $expect_error);
 286     exit;
 287 }
 288
 289 ########
 290
 291 ##
 292 # A simple, one-part FILE-WRITE
 293 $handle = "11-11111";
 294 $datestamp = "20070102030405";
 295 run_taper(4096, "single-part and multipart FILE-WRITE");
 296 like(taper_reply, qr/^TAPER-OK worker0$/,
 297         "got TAPER-OK") or die;
 298 make_holding_file(1024*1024, "localhost", "/home");
 299 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp \"\" \"\" \"\" \"\" \"\" \"\" \"\" \"\" 12");
 300 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 301         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 302 taper_cmd("START-SCAN worker0 $handle");
 303 taper_cmd("NEW-TAPE worker0 $handle");
 304 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 305         "got proper NEW-TAPE worker0 $handle") or die;
 306 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 1024 "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]"$/,
 307         "got PARTDONE") or die;
 308 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]" "" ""$/,
 309         "got DONE") or die;
 310
 311 ##
 312 # A multipart FILE-WRITE, using the same taper instance
 313 #  (note that the third part is of length 0, and is not logged)
 314
 315 $handle = '11-22222';
 316 make_holding_file(1024*1024, "localhost", "/usr");
 317 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 524288 \"\" \"\" 1 \"\" \"\" \"\" \"\" 512");
 318 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 512 "\[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]"$/,
 319         "got PARTDONE for filenum 2") or die;
 320 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 512 "\[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]"$/,
 321         "got PARTDONE for filenum 3") or die;
 322 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 512\]" "" ""$/,
 323         "got DONE") or die;
 324 taper_cmd("QUIT");
 325 wait_for_exit();
 326
 327 check_logs([
 328     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 329     qr(^PART taper TESTCONF01 1 localhost /home $datestamp 1/-1 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]$),
 330     qr(^DONE taper localhost /home $datestamp 1 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]$),
 331     qr(^PART taper TESTCONF01 2 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]$),
 332     qr(^PART taper TESTCONF01 3 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]$),
 333     qr(^DONE taper localhost /usr $datestamp 2 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 512\]$),
 334     qr(^INFO taper tape TESTCONF01 kb 2048 fm 4 \[OK\]$),
 335 ], "single-part and multi-part dump logged correctly");
 336
 337 # check out the headers on those files, just to be sure
 338 {
 339     my $dev = Amanda::Device->new("file:" . Installcheck::Run::vtape_dir());
 340     die("bad device: " . $dev->error_or_status()) unless $dev->status == $DEVICE_STATUS_SUCCESS;
 341
 342     $dev->start($ACCESS_READ, undef, undef)
 343         or die("can't start device: " . $dev->error_or_status());
 344
 345     sub is_hdr {
 346         my ($hdr, $expected, $msg) = @_;
 347         my $got = {};
 348         for (keys %$expected) { $got->{$_} = "".$hdr->{$_}; }
 349         if (!is_deeply($got, $expected, $msg)) {
 350             diag("got: " . Dumper($got));
 351         }
 352     }
 353
 354     is_hdr($dev->seek_file(1), {
 355         type => $F_SPLIT_DUMPFILE,
 356         datestamp => $datestamp,
 357         name => 'localhost',
 358         disk => '/home',
 359     }, "header on file 1 is correct");
 360
 361     is_hdr($dev->seek_file(2), {
 362         type => $F_SPLIT_DUMPFILE,
 363         datestamp => $datestamp,
 364         name => 'localhost',
 365         disk => '/usr',
 366         partnum => 1,
 367         totalparts => -1,
 368     }, "header on file 2 is correct");
 369
 370     is_hdr($dev->seek_file(3), {
 371         type => $F_SPLIT_DUMPFILE,
 372         datestamp => $datestamp,
 373         name => 'localhost',
 374         disk => '/usr',
 375         partnum => 2,
 376         totalparts => -1,
 377     }, "header on file 3 is correct");
 378
 379     is_hdr($dev->seek_file(4), {
 380         type => $F_SPLIT_DUMPFILE,
 381         datestamp => $datestamp,
 382         name => 'localhost',
 383         disk => '/usr',
 384         partnum => 3,
 385         totalparts => -1,
 386     }, "header on file 4 is correct");
 387 }
 388
 389 ##
 390 # A PORT-WRITE with no disk buffer
 391
 392 $handle = "11-33333";
 393 $datestamp = "19780615010203";
 394 run_taper(4096, "multipart PORT-WRITE");
 395 like(taper_reply, qr/^TAPER-OK worker0$/,
 396         "got TAPER-OK") or die;
 397 taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 524288 \"\" 393216 1 0 \"\" \"\" 0 AMANDA");
 398 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 399         "got PORT with data address");
 400 write_to_port($last_taper_reply, 63*32768, "localhost", "/var", 0);
 401 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 402         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 403 taper_cmd("START-SCAN worker0 $handle");
 404 taper_cmd("NEW-TAPE worker0 $handle");
 405 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 406         "got proper NEW-TAPE worker0 $handle") or die;
 407 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
 408         "got PARTDONE for filenum 1") or die;
 409 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
 410         "got PARTDONE for filenum 2") or die;
 411 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
 412         "got PARTDONE for filenum 3") or die;
 413 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
 414         "got PARTDONE for filenum 4") or die;
 415 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 5 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
 416         "got PARTDONE for filenum 5") or die;
 417 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 6 96 "\[sec [\d.]+ kb 96 kps [\d.]+\]"$/,
 418         "got PARTDONE for filenum 6") or die;
 419 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 420         "got DUMPER-STATUS request") or die;
 421 taper_cmd("DONE worker0 $handle 712");
 422 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 2016 kps [\d.]+ orig-kb 712\]" "" ""$/,
 423         "got DONE") or die;
 424 taper_cmd("QUIT");
 425 wait_for_exit();
 426
 427 check_logs([
 428     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 429     qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
 430     qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
 431     qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
 432     qr(^PART taper TESTCONF01 4 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
 433     qr(^PART taper TESTCONF01 5 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
 434     qr(^PART taper TESTCONF01 6 localhost /var $datestamp 6/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+\]$),
 435     qr(^DONE taper localhost /var $datestamp 6 0 \[sec [\d.]+ kb 2016 kps [\d.]+ orig-kb 712\]$),
 436     qr(^INFO taper tape TESTCONF01 kb 2016 fm 6 \[OK\]$),
 437 ], "multipart PORT-WRITE logged correctly");
 438
 439 ##
 440 # Test NO-NEW-TAPE
 441
 442 $handle = "11-44444";
 443 $datestamp = "19411207000000";
 444 run_taper(4096, "testing NO-NEW-TAPE from the driver on 1st request");
 445 like(taper_reply, qr/^TAPER-OK worker0$/,
 446         "got TAPER-OK") or die;
 447 make_holding_file(1024*1024, "localhost", "/home");
 448 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp 0 \"\" 0 1 0 \"\" \"\" 0 912");
 449 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 450         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 451 taper_cmd("NO-NEW-TAPE worker0 $handle sorry");
 452 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
 453         "got FAILED") or die;
 454 taper_cmd("QUIT");
 455 wait_for_exit();
 456
 457 check_logs([
 458     qr(^ERROR taper no-tape config \[sorry\]$),
 459     qr(^FAIL taper localhost /home $datestamp 0 config sorry$),
 460 ], "NO-NEW-TAPE logged correctly");
 461
 462 ##
 463 # Test retrying on EOT (via PORT-WRITE with a mem cache)
 464
 465 $handle = "11-55555";
 466 $datestamp = "19750711095836";
 467 run_taper(1024, "PORT-WRITE retry on EOT (mem cache)");
 468 like(taper_reply, qr/^TAPER-OK worker0$/,
 469         "got TAPER-OK") or die;
 470 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"\" 786432 1 0 \"\" \"\" 0 AMANDA");
 471 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 472         "got PORT with data address");
 473 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
 474 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 475         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 476 taper_cmd("START-SCAN worker0 $handle");
 477 taper_cmd("NEW-TAPE worker0 $handle");
 478 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 479         "got proper NEW-TAPE worker0 $handle") or die;
 480 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
 481         "got PARTDONE for filenum 1") or die;
 482 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 483         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 484 taper_cmd("START-SCAN worker0 $handle");
 485 taper_cmd("NEW-TAPE worker0 $handle");
 486 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 487         "got proper NEW-TAPE worker0 $handle") or die;
 488 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
 489         "got PARTDONE for filenum 1 on second tape") or die;
 490 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+\]"$/,
 491         "got PARTDONE for filenum 2 on second tape") or die;
 492 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 493         "got DUMPER-STATUS request") or die;
 494 taper_cmd("DONE worker0 $handle 1012");
 495 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1012\]" "" ""$/,
 496         "got DONE") or die;
 497 taper_cmd("QUIT");
 498 wait_for_exit();
 499
 500 check_logs([
 501     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 502     qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
 503     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+\] "No space left on device"$),
 504     qr(^INFO taper Will request retry of failed split part\.$),
 505     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 506     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 507     qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
 508     qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+\]$),
 509     qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1012\]$),
 510     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 511 ], "multivolume PORT-WRITE logged correctly");
 512
 513 ##
 514 # Test retrying on EOT (via FILE-WRITE)
 515
 516 $handle = "11-66666";
 517 $datestamp = "19470815000000";
 518 run_taper(1024, "FILE-WRITE retry on EOT");
 519 like(taper_reply, qr/^TAPER-OK worker0$/,
 520         "got TAPER-OK") or die;
 521 make_holding_file(1575936, "localhost", "/usr");
 522 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp \"\" \"\" \"\" 1 786432 \"\" \"\" \"\" 1112");
 523 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 524         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 525 taper_cmd("START-SCAN worker0 $handle");
 526 taper_cmd("NEW-TAPE worker0 $handle");
 527 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 528         "got proper NEW-TAPE worker0 $handle") or die;
 529 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]"$/,
 530         "got PARTDONE for filenum 1") or die;
 531 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 532         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 533 taper_cmd("START-SCAN worker0 $handle");
 534 taper_cmd("NEW-TAPE worker0 $handle");
 535 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 536         "got proper NEW-TAPE worker0 $handle") or die;
 537 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]"$/,
 538         "got PARTDONE for filenum 1 on second tape") or die;
 539 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+ orig-kb 1112\]"$/,
 540         "got PARTDONE for filenum 2 on second tape") or die;
 541 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1112\]" "" ""$/,
 542         "got DONE") or die;
 543 taper_cmd("QUIT");
 544 wait_for_exit();
 545
 546 check_logs([
 547     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 548     qr(^PART taper TESTCONF01 1 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]$),
 549     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+ orig-kb 1112\] "No space left on device"$),
 550     qr(^INFO taper Will request retry of failed split part\.$),
 551     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 552     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 553     qr(^PART taper TESTCONF02 1 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]$),
 554     qr(^PART taper TESTCONF02 2 localhost /usr $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+ orig-kb 1112\]$),
 555     qr(^DONE taper localhost /usr $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1112\]$),
 556     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 557 ], "multivolume FILE-WRITE logged correctly");
 558
 559 ##
 560 # Test retrying on EOT (via PORT-WRITE with a disk cache)
 561
 562 $handle = "11-77777";
 563 $datestamp = "20090427212500";
 564 run_taper(1024, "PORT-WRITE retry on EOT (disk cache)");
 565 like(taper_reply, qr/^TAPER-OK worker0$/,
 566         "got TAPER-OK") or die;
 567 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"$Installcheck::TMP\" 786432 1 0 \"\" \"\" 0 AMANDA");
 568 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 569         "got PORT with data address");
 570 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
 571 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 572         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 573 taper_cmd("START-SCAN worker0 $handle");
 574 taper_cmd("NEW-TAPE worker0 $handle");
 575 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 576         "got proper NEW-TAPE worker0 $handle") or die;
 577 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
 578         "got PARTDONE for filenum 1") or die;
 579 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 580         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 581 taper_cmd("START-SCAN worker0 $handle");
 582 taper_cmd("NEW-TAPE worker0 $handle");
 583 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 584         "got proper NEW-TAPE worker0 $handle") or die;
 585 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
 586         "got PARTDONE for filenum 1 on second tape") or die;
 587 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+\]"$/,
 588         "got PARTDONE for filenum 2 on second tape") or die;
 589 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 590         "got DUMPER-STATUS request") or die;
 591 taper_cmd("DONE worker0 $handle 1212");
 592 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1212\]" "" ""$/,
 593         "got DONE") or die;
 594 taper_cmd("QUIT");
 595 wait_for_exit();
 596
 597 check_logs([
 598     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 599     qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
 600     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+\] "No space left on device"$),
 601     qr(^INFO taper Will request retry of failed split part\.$),
 602     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 603     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 604     qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
 605     qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+\]$),
 606     qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1212\]$),
 607     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 608 ], "multivolume PORT-WRITE (disk cache) logged correctly");
 609
 610 ##
 611 # Test failure on EOT (via PORT-WRITE with no cache), and a new try on the
 612 # next tape.
 613
 614 $handle = "11-88888";
 615 $datestamp = "20090424173000";
 616 run_taper(1024, "PORT-WRITE failure on EOT (no cache)");
 617 like(taper_reply, qr/^TAPER-OK worker0$/,
 618         "got TAPER-OK") or die;
 619 taper_cmd("PORT-WRITE worker0 $handle localhost /var/log 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
 620 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 621         "got PORT with data address");
 622 write_to_port($last_taper_reply, 1575936, "localhost", "/var/log", 1);
 623 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 624         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 625 taper_cmd("START-SCAN worker0 $handle");
 626 taper_cmd("NEW-TAPE worker0 $handle");
 627 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 628         "got proper NEW-TAPE worker0 $handle") or die;
 629 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ kb 0 kps [\d.]+\]" "" "No space left on device"$/,
 630         "got PARTIAL") or die;
 631 # retry on the next tape
 632 $handle = "11-88899";
 633 taper_cmd("PORT-WRITE worker0 $handle localhost /boot 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
 634 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 635         "got PORT with data address");
 636 write_to_port($last_taper_reply, 65536, "localhost", "/boot", 0);
 637 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 638         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 639 taper_cmd("START-SCAN worker0 $handle");
 640 taper_cmd("NEW-TAPE worker0 $handle");
 641 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 642         "got proper NEW-TAPE worker0 $handle") or die;
 643 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 64 "\[sec [\d.]+ kb 64 kps [\d.]+\]"$/,
 644         "got PARTDONE for filenum 1 on second tape") or die;
 645 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 646         "got DUMPER-STATUS request") or die;
 647 taper_cmd("DONE worker0 $handle 64");
 648 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 64 kps [\d.]+ orig-kb 64\]" "" ""$/,
 649         "got DONE") or die;
 650 taper_cmd("QUIT");
 651 wait_for_exit();
 652
 653 check_logs([
 654     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 655     qr(^PARTPARTIAL taper TESTCONF01 1 localhost /var/log $datestamp 1/-1 0 \[sec [\d.]+ kb 960 kps [\d.]+\] "No space left on device"$),
 656     qr(^PARTIAL taper localhost /var/log $datestamp 1 0 \[sec [\d.]+ kb 0 kps [\d.]+\] "No space left on device"$),
 657     qr(^INFO taper tape TESTCONF01 kb 0 fm 1 \[OK\]$),
 658     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 659     qr(^PART taper TESTCONF02 1 localhost /boot $datestamp 1/-1 0 \[sec [\d.]+ kb 64 kps [\d.]+\]$),
 660     qr(^DONE taper localhost /boot $datestamp 1 0 \[sec [\d.]+ kb 64 kps [\d.]+ orig-kb 64\]$),
 661     qr(^INFO taper tape TESTCONF02 kb 64 fm 1 \[OK\]$),
 662 ], "failure on EOT (no cache) with subsequent dump logged correctly");
 663
 664 ##
 665 # Test running out of tapes (second REQUEST-NEW-TAPE fails)
 666
 667 $handle = "11-99999";
 668 $datestamp = "20100101000000";
 669 run_taper(512, "FILE-WRITE runs out of tapes");
 670 like(taper_reply, qr/^TAPER-OK worker0$/,
 671         "got TAPER-OK") or die;
 672 make_holding_file(512*1024, "localhost", "/music");
 673 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /music 0 $datestamp \"\" \"\" \"\" 1 262144 \"none\" \"\" 10240 1312");
 674 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 675         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 676 taper_cmd("START-SCAN worker0 $handle");
 677 taper_cmd("NEW-TAPE worker0 $handle");
 678 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 679         "got proper NEW-TAPE worker0 $handle") or die;
 680 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]"$/,
 681         "got PARTDONE for filenum 1 on first tape") or die;
 682 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 683         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 684 taper_cmd("NO-NEW-TAPE worker0 $handle \"that's enough\"");
 685 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]" "" "that's enough"$/,
 686         "got PARTIAL") or die;
 687 taper_cmd("QUIT");
 688 wait_for_exit();
 689
 690 check_logs([
 691     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 692     qr(^PART taper TESTCONF01 1 localhost /music $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]$),
 693     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /music $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+ orig-kb 1312\] "No space left on device"$),
 694     qr(^INFO taper Will request retry of failed split part\.$),
 695     qr(^INFO taper tape TESTCONF01 kb 256 fm 2 \[OK\]$),
 696     qr(^ERROR taper no-tape config \[that's enough\]$),
 697     qr(^PARTIAL taper localhost /music $datestamp 2 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\] "that's enough"$),
 698 ], "running out of tapes (simulating runtapes=1) logged correctly");
 699
 700 ##
 701 # A PORT-WRITE with no disk buffer
 702
 703 $handle = "22-00000";
 704 $datestamp = "20200202222222";
 705 run_taper(4096, "multipart PORT-WRITE");
 706 like(taper_reply, qr/^TAPER-OK worker0$/,
 707         "got TAPER-OK") or die;
 708 taper_cmd("PORT-WRITE worker0 $handle localhost /sbin 0 $datestamp 999999 \"\" 655360 1 \"\" \"\" \"\" \"\" AMANDA");
 709 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 710         "got PORT with data address");
 711 write_to_port($last_taper_reply, 63*32768, "localhost", "/sbin", 0);
 712 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 713         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 714 taper_cmd("START-SCAN worker0 $handle");
 715 taper_cmd("NEW-TAPE worker0 $handle");
 716 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 717         "got proper NEW-TAPE worker0 $handle") or die;
 718 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
 719         "got PARTDONE for filenum 1") or die;
 720 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
 721         "got PARTDONE for filenum 2") or die;
 722 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
 723         "got PARTDONE for filenum 3") or die;
 724 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 96 "\[sec [\d.]+ kb 96 kps [\d.]+\]"$/,
 725         "got PARTDONE for filenum 4") or die;
 726 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 727         "got DUMPER-STATUS request") or die;
 728 taper_cmd("FAILED worker0 $handle");
 729 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 2016 kps [\d.]+\]" "" ""$/,
 730         "got DONE") or die;
 731 taper_cmd("QUIT");
 732 wait_for_exit();
 733
 734 check_logs([
 735     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 736     qr(^PART taper TESTCONF01 1 localhost /sbin $datestamp 1/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
 737     qr(^PART taper TESTCONF01 2 localhost /sbin $datestamp 2/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
 738     qr(^PART taper TESTCONF01 3 localhost /sbin $datestamp 3/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
 739     qr(^PART taper TESTCONF01 4 localhost /sbin $datestamp 4/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+\]$),
 740     qr(^PARTIAL taper localhost /sbin $datestamp 4 0 \[sec [\d.]+ kb 2016 kps [\d.]+\]$), # note no error message
 741     qr(^INFO taper tape TESTCONF01 kb 2016 fm 4 \[OK\]$),
 742 ], "DUMPER_STATUS => FAILED logged correctly");
 743
 744 ##
 745 # Test a sequence of writes to the same set of tapes
 746
 747 $handle = "33-11111";
 748 $datestamp = "20090101010000";
 749 run_taper(1024, "first in a sequence");
 750 like(taper_reply, qr/^TAPER-OK worker0$/,
 751         "got TAPER-OK") or die;
 752 make_holding_file(500000, "localhost", "/u01");
 753 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1412");
 754 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 755         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 756 taper_cmd("START-SCAN worker0 $handle");
 757 taper_cmd("NEW-TAPE worker0 $handle");
 758 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 759         "got proper NEW-TAPE worker0 $handle") or die;
 760 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1412\]"$/,
 761         "got PARTDONE for filenum 1") or die;
 762 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 232 "\[sec [\d.]+ kb 232 kps [\d.]+ orig-kb 1412\]"$/,
 763         "got PARTDONE for filenum 2") or die;
 764 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 488 kps [\d.]+ orig-kb 1412\]" "" ""$/,
 765         "got DONE") or die;
 766 $handle = "33-22222";
 767 make_holding_file(614400, "localhost", "/u02");
 768 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1512");
 769 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]"$/,
 770         "got PARTDONE for filenum 3") or die;
 771 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 772         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 773 taper_cmd("START-SCAN worker0 $handle");
 774 taper_cmd("NEW-TAPE worker0 $handle");
 775 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 776         "got proper NEW-TAPE worker0 $handle") or die;
 777 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]"$/,
 778         "got PARTDONE for filenum 1 on second tape") or die;
 779 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1512\]"$/,
 780         "got PARTDONE for filenum 2 on second tape") or die;
 781 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1512\]" "" ""$/,
 782         "got DONE") or die;
 783 taper_cmd("QUIT");
 784 wait_for_exit();
 785
 786 check_logs([
 787     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 788     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1412\]$),
 789     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 232 kps [\d.]+ orig-kb 1412\]$),
 790     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 488 kps [\d.]+ orig-kb 1412\]$),
 791     qr(^PART taper TESTCONF01 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]$),
 792     qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+ orig-kb 1512\] "No space left on device"$),
 793     qr(^INFO taper Will request retry of failed split part\.$),
 794     qr(^INFO taper tape TESTCONF01 kb 744 fm 4 \[OK\]$),
 795     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 796     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]$),
 797     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1512\]$),
 798     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1512\]$),
 799     qr(^INFO taper tape TESTCONF02 kb 344 fm 2 \[OK\]$),
 800 ], "first taper invocation in sequence logged correctly");
 801 cleanup_log();
 802
 803 $handle = "33-33333";
 804 $datestamp = "20090202020000";
 805 run_taper(1024, "second in a sequence", keep_config => 1);
 806 like(taper_reply, qr/^TAPER-OK worker0$/,
 807         "got TAPER-OK") or die;
 808 make_holding_file(300000, "localhost", "/u01");
 809 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
 810 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 811         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 812 taper_cmd("START-SCAN worker0 $handle");
 813 taper_cmd("NEW-TAPE worker0 $handle");
 814 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF03$/,
 815         "got proper NEW-TAPE worker0 $handle") or die;
 816 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
 817         "got PARTDONE for filenum 1") or die;
 818 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 2 36 "\[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]"$/,
 819         "got PARTDONE for filenum 2") or die;
 820 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]" "" ""$/,
 821         "got DONE") or die;
 822 $handle = "33-44444";
 823 make_holding_file(614400, "localhost", "/u02");
 824 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
 825 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
 826         "got PARTDONE for filenum 3") or die;
 827 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 4 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
 828         "got PARTDONE for filenum 4") or die;
 829 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 830         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 831 taper_cmd("START-SCAN worker0 $handle");
 832 taper_cmd("NEW-TAPE worker0 $handle");
 833 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 834         "got proper NEW-TAPE worker0 $handle") or die;
 835 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]"$/,
 836         "got PARTDONE for filenum 1 on second tape") or die;
 837 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]" "" ""$/,
 838         "got DONE") or die;
 839 taper_cmd("QUIT");
 840 wait_for_exit();
 841
 842 check_logs([
 843     qr(^START taper datestamp $datestamp label TESTCONF03 tape 1$),
 844     qr(^PART taper TESTCONF03 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
 845     qr(^PART taper TESTCONF03 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]$),
 846     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]$),
 847     qr(^PART taper TESTCONF03 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
 848     qr(^PART taper TESTCONF03 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
 849     qr(^PARTPARTIAL taper TESTCONF03 5 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 0 kps [\d.]+ orig-kb 1712\] "No space left on device"$),
 850     qr(^INFO taper Will request retry of failed split part\.$),
 851     qr(^INFO taper tape TESTCONF03 kb 804 fm 5 \[OK\]$),
 852     qr(^START taper datestamp $datestamp label TESTCONF01 tape 2$),
 853     qr(^PART taper TESTCONF01 1 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]$),
 854     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]$),
 855     qr(^INFO taper tape TESTCONF01 kb 88 fm 1 \[OK\]$),
 856 ], "second taper invocation in sequence logged correctly");
 857 cleanup_log();
 858
 859 ##
 860 # test failure to overwrite a tape label
 861
 862 $handle = "33-55555";
 863 $datestamp = "20090303030000";
 864 run_taper(1024, "failure to overwrite a volume", keep_config => 1);
 865 like(taper_reply, qr/^TAPER-OK worker0$/,
 866         "got TAPER-OK") or die;
 867 make_holding_file(32768, "localhost", "/u03");
 868 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u03 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1812");
 869 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 870         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 871 # we've secretly replaced the tape in slot 1 with a read-only tape.. let's see
 872 # if anyone can tell the difference!
 873 chmod(0555, Installcheck::Run::vtape_dir(2));
 874 taper_cmd("START-SCAN worker0 $handle");
 875 taper_cmd("NEW-TAPE worker0 $handle");
 876 # NO-NEW-TAPE indicates it did *not* overwrite the tape
 877 like(taper_reply, qr/^NO-NEW-TAPE $handle$/,
 878         "got proper NO-NEW-TAPE worker0 $handle"); # no "die" here, so we can restore perms
 879 chmod(0755, Installcheck::Run::vtape_dir(2));
 880 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 881         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 882 taper_cmd("NO-NEW-TAPE worker0 $handle \"sorry\"");
 883 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
 884         "got FAILED") or die;
 885 taper_cmd("QUIT");
 886 wait_for_exit();
 887
 888 # (logs aren't that interesting here - filled with VFS-specific error messages)
 889
 890 # TODO: simulate an "erased" tape, to which taper should reply with "NEW-TAPE worker0 $handle" and
 891 # immediately REQUEST-NEW-TAPE.  I can't see a way to make the VFS device erase a
 892 # volume without start_device succeeding.
 893
 894 ##
 895 # A run with a bogus tapedev/tpchanger
 896 $handle = "44-11111";
 897 $datestamp = "20070102030405";
 898 run_taper(4096, "no tapedev", notapedev => 1);
 899 like(taper_reply, qr/^TAPE-ERROR SETUP "You must specify one of 'tapedev' or 'tpchanger'"$/,
 900         "got TAPE-ERROR") or die;
 901 wait_for_exit();
 902
 903 ##
 904 # A run with 2 workers
 905 my $handle0 = "66-00000";
 906 my $handle1 = "66-11111";
 907 $datestamp = "20090202020000";
 908 run_taper(1024, "with 2 workers", new_vtapes => 1);
 909 like(taper_reply, qr/^TAPER-OK worker0$/,
 910         "got TAPER-OK") or die;
 911 taper_cmd("START-TAPER worker1 $datestamp");
 912 like(taper_reply, qr/^TAPER-OK worker1$/,
 913        "got TAPER-OK") or die;
 914 make_holding_file(300000, "localhost", "/u01");
 915 taper_cmd("FILE-WRITE worker0 $handle0 \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
 916 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle0$/,
 917         "got REQUEST-NEW-TAPE worker0 $handle0") or die;
 918 taper_cmd("START-SCAN worker0 $handle0");
 919 taper_cmd("NEW-TAPE worker0 $handle0");
 920 like(taper_reply, qr/^NEW-TAPE $handle0 TESTCONF01$/,
 921         "got proper NEW-TAPE worker0 $handle0") or die;
 922 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
 923         "got PARTDONE for filenum 1") or die;
 924 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 2 36 "\[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]"$/,
 925         "got PARTDONE for filenum 2") or die;
 926 like(taper_reply, qr/^DONE $handle0 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]" "" ""$/,
 927         "got DONE") or die;
 928 make_holding_file(614400, "localhost", "/u02");
 929 taper_cmd("FILE-WRITE worker1 $handle1 \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
 930 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle1$/,
 931         "got REQUEST-NEW-TAPE worker1 $handle1") or die;
 932 taper_cmd("START-SCAN worker1 $handle1");
 933 taper_cmd("NEW-TAPE worker1 $handle1");
 934 like(taper_reply, qr/^NEW-TAPE $handle1 TESTCONF02$/,
 935         "got proper NEW-TAPE worker1 $handle1") or die;
 936 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
 937         "got PARTDONE for filenum 1 on second tape") or die;
 938 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 2 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
 939         "got PARTDONE for filenum 2 on second tape") or die;
 940 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 3 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]"$/,
 941         "got PARTDONE for filenum 3 on second tape") or die;
 942 like(taper_reply, qr/^DONE $handle1 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]" "" ""$/,
 943         "got DONE") or die;
 944 taper_cmd("QUIT");
 945 wait_for_exit();
 946
 947 check_logs([
 948     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 949     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
 950     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]$),
 951     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]$),
 952     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 953     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
 954     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
 955     qr(^PART taper TESTCONF02 3 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]$),
 956     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]$),
 957     qr(^INFO taper tape TESTCONF01 kb 292 fm 2 \[OK\]$),
 958     qr(^INFO taper tape TESTCONF02 kb 600 fm 3 \[OK\]$),
 959 ], "two workers logged correctly");
 960 cleanup_log();
 961
 962 ##
 963 # A run with 2 workers and a take_scribe
 964 $handle = "66-22222";
 965 $datestamp = "20090202020000";
 966 run_taper(1024, "with 2 workers and a take_scribe", new_vtapes => 1);
 967 like(taper_reply, qr/^TAPER-OK worker0$/,
 968         "got TAPER-OK") or die;
 969 taper_cmd("START-TAPER worker1 $datestamp");
 970 like(taper_reply, qr/^TAPER-OK worker1$/,
 971         "got TAPER-OK") or die;
 972 make_holding_file(1000000, "localhost", "/u01");
 973 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
 974 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 975         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 976 taper_cmd("START-SCAN worker0 $handle");
 977 taper_cmd("NEW-TAPE worker0 $handle");
 978 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 979         "got proper NEW-TAPE worker0 $handle") or die;
 980 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
 981         "got PARTDONE for filenum 1") or die;
 982 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
 983         "got PARTDONE for filenum 2") or die;
 984 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
 985         "got PARTDONE for filenum 3") or die;
 986 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 987         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 988 taper_cmd("TAKE-SCRIBE-FROM worker0 $handle worker1");
 989 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 990         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 991 taper_cmd("START-SCAN worker0 $handle");
 992 taper_cmd("NEW-TAPE worker0 $handle");
 993 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 994         "got proper NEW-TAPE worker0 $handle") or die;
 995 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 208 "\[sec [\d.]+ kb 208 kps [\d.]+ orig-kb 1612\]"$/,
 996         "got PARTDONE for filenum 4") or die;
 997 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 976 kps [\d.]+ orig-kb 1612\]" "" ""$/,
 998         "got DONE") or die;
 999 taper_cmd("QUIT");
1000 wait_for_exit();
1001
1002 check_logs([
1003     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1004     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1005     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1006     qr(^PART taper TESTCONF01 3 localhost /u01 $datestamp 3/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1007     qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+ orig-kb 1612\] \"No space left on device\"$),
1008     qr(^INFO taper Will request retry of failed split part.$),
1009     qr(^INFO taper tape TESTCONF01 kb 768 fm 4 \[OK\]$),
1010     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1011     qr(^PART taper TESTCONF02 1 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ kb 208 kps [\d.]+ orig-kb 1612\]$),
1012     qr(^DONE taper localhost /u01 $datestamp 4 0 \[sec [\d.]+ kb 976 kps [\d.]+ orig-kb 1612\]$),
1013     qr(^INFO taper tape TESTCONF02 kb 208 fm 1 \[OK\]$),
1014 ], "TAKE-SCRIBE logged correctly");
1015 cleanup_log();
1016
1017 ##
1018 # Test with NDMP device (DirectTCP)
1019
1020 SKIP : {
1021     skip "not built with NDMP", 33 unless Amanda::Util::built_with_component("ndmp");
1022
1023     my $ndmp = Installcheck::Mock::NdmpServer->new(tape_limit => 1024*1024);
1024     my $ndmp_port = $ndmp->{'port'};
1025     my $drive = $ndmp->{'drive'};
1026
1027     $handle = "55-11111";
1028     $datestamp = "19780615010305";
1029     run_taper(4096, "multipart directtcp PORT-WRITE",
1030         ndmp_server => $ndmp);
1031     like(taper_reply, qr/^TAPER-OK worker0$/,
1032             "got TAPER-OK") or die;
1033     # note that, with the addition of the new splitting params, this does the "sensible"
1034     # thing and uses the tape_splitsize, not the fallback_splitsize (this is a change from
1035     # Amanda-3.1)
1036     taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 393216 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1037     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1038             "got PORT with data address");
1039     write_to_port($last_taper_reply, 1230*1024, "localhost", "/var", 0);
1040     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1041             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1042     taper_cmd("START-SCAN worker0 $handle");
1043     taper_cmd("NEW-TAPE worker0 $handle");
1044     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1045             "got proper NEW-TAPE worker0 $handle") or die;
1046     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1047             "got PARTDONE for part 1") or die;
1048     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1049             "got PARTDONE for part 2") or die;
1050     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 64 "\[sec [\d.]+ kb 64 kps [\d.]+\]"$/,
1051             "got PARTDONE for part 3 (short part)") or die;
1052     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1053             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1054     taper_cmd("START-SCAN worker0 $handle");
1055     taper_cmd("NEW-TAPE worker0 $handle");
1056     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1057             "got proper NEW-TAPE worker0 $handle") or die;
1058     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1059             "got PARTDONE for part 4") or die;
1060     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 32 "\[sec [\d.]+ kb 32 kps [\d.]+\]"$/,
1061             "got PARTDONE for part 5") or die;
1062     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1063             "got DUMPER-STATUS request") or die;
1064     taper_cmd("DONE worker0 $handle 1912");
1065     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1248 kps [\d.]+ orig-kb 1912\]" "" ""$/,
1066             "got DONE") or die;
1067     $handle = "55-22222";
1068     taper_cmd("PORT-WRITE worker0 $handle localhost /etc 0 $datestamp 524288 \"\" 393216 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1069     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1070             "got PORT with data address");
1071     write_to_port($last_taper_reply, 300*1024, "localhost", "/etc", 0);
1072     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 3 320 "\[sec [\d.]+ kb 320 kps [\d.]+\]"$/,
1073             "got PARTDONE for part 1") or die;
1074     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1075             "got DUMPER-STATUS request") or die;
1076     taper_cmd("DONE worker0 $handle 2012");
1077     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 320 kps [\d.]+ orig-kb 2012\]" "" ""$/,
1078             "got DONE") or die;
1079     taper_cmd("QUIT");
1080     wait_for_exit();
1081
1082     check_logs([
1083         qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1084         qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1085         qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1086         qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 64 kps [\d.]+\]$),
1087         # note no "Will retry.."
1088         qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1089         qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1090         qr(^PART taper TESTCONF02 1 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1091         qr(^PART taper TESTCONF02 2 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ kb 32 kps [\d.]+\]$),
1092         qr(^DONE taper localhost /var $datestamp 5 0 \[sec [\d.]+ kb 1248 kps [\d.]+ orig-kb 1912\]$),
1093         qr(^PART taper TESTCONF02 3 localhost /etc $datestamp 1/-1 0 \[sec [\d.]+ kb 320 kps [\d.]+\]$),
1094         qr(^DONE taper localhost /etc $datestamp 1 0 \[sec [\d.]+ kb 320 kps [\d.]+ orig-kb 2012\]$),
1095         qr(^INFO taper tape TESTCONF02 kb 736 fm 3 \[OK\]$),
1096     ], "multipart directtcp PORT-WRITE logged correctly");
1097
1098     $handle = "55-33333";
1099     $datestamp = "19780615010305";
1100     run_taper(4096, "multipart directtcp PORT-WRITE, with a zero-byte part",
1101         ndmp_server => $ndmp);
1102     like(taper_reply, qr/^TAPER-OK worker0$/,
1103             "got TAPER-OK") or die;
1104     # use a different part size this time, to hit EOM "on the head"
1105     taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 425984 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1106     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1107             "got PORT with data address");
1108     write_to_port($last_taper_reply, 1632*1024, "localhost", "/var", 0);
1109     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1110             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1111     taper_cmd("START-SCAN worker0 $handle");
1112     taper_cmd("NEW-TAPE worker0 $handle");
1113     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1114             "got proper NEW-TAPE worker0 $handle") or die;
1115     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1116             "got PARTDONE for part 1") or die;
1117     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1118             "got PARTDONE for part 2") or die;
1119     # note: zero-byte part is not reported as PARTDONE
1120     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1121             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1122     taper_cmd("START-SCAN worker0 $handle");
1123     taper_cmd("NEW-TAPE worker0 $handle");
1124     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1125             "got proper NEW-TAPE worker0 $handle") or die;
1126     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1127             "got PARTDONE for part 3") or die;
1128     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1129             "got PARTDONE for part 4") or die;
1130     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1131             "got DUMPER-STATUS request") or die;
1132     taper_cmd("DONE worker0 $handle 2112");
1133     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1632 kps [\d.]+ orig-kb 2112\]" "" ""$/,
1134             "got DONE") or die;
1135     taper_cmd("QUIT");
1136     wait_for_exit();
1137
1138     check_logs([
1139         qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1140         qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1141         qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1142         # Note: zero-byte part is not logged, but is counted in this INFO line's 'fm' field
1143         qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1144         qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1145         qr(^PART taper TESTCONF02 1 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1146         qr(^PART taper TESTCONF02 2 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1147         qr(^DONE taper localhost /var $datestamp 4 0 \[sec [\d.]+ kb 1632 kps [\d.]+ orig-kb 2112\]$),
1148         qr(^INFO taper tape TESTCONF02 kb 800 fm 2 \[OK\]$),
1149     ], "multipart directtcp PORT-WRITE with a zero-byte part logged correctly");
1150     cleanup_log();
1151
1152     $ndmp->cleanup();
1153 } # end of ndmp SKIP
1154
1155 cleanup_taper();