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