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 => 269;
  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         if ($params{'taperscan'}) {
  91             $testconf->add_param('taperscan', "\"$params{'taperscan'}\"");
  92             $testconf->add_taperscan($params{'taperscan'}, [
  93                         'comment' => '"my taperscan is mine, not yours"',
  94                         'plugin'  => "\"$params{'taperscan'}\"",
  95                         ]);
  96
  97         }
  98         $testconf->write();
  99     }
 100
 101     open(TAPER_ERR, ">", $taper_stderr_file);
 102     $taper_in = $taper_out = '';
 103     $taper_pid = open3($taper_in, $taper_out, ">&TAPER_ERR",
 104         "$amlibexecdir/taper", "TESTCONF");
 105     close TAPER_ERR;
 106     $taper_in->blocking(1);
 107     $taper_out->autoflush();
 108
 109     if ($params{'keep_config'}) {
 110         pass("spawned new taper for $description (same config)");
 111     } else {
 112         pass("spawned taper for $description (tape length $length kb)");
 113     }
 114
 115     # define this to get the installcheck to wait and allow you to attach
 116     # a gdb instance to the taper
 117     if ($params{'use_gdb'}) {
 118         $taper_reply_timeout = 0; # no timeouts while debugging
 119         diag("attach debugger to pid $taper_pid and press ENTER");
 120         <>;
 121     } else {
 122         $taper_reply_timeout = 120;
 123     }
 124
 125     taper_cmd("START-TAPER worker0 $datestamp");
 126 }
 127
 128 sub wait_for_exit {
 129     if ($taper_pid) {
 130         waitpid($taper_pid, 0);
 131         $taper_pid = undef;
 132     }
 133 }
 134
 135 sub cleanup_taper {
 136     -f $test_filename and unlink($test_filename);
 137     -f $taper_stderr_file and unlink($taper_stderr_file);
 138
 139     # make a small effort to collect zombies
 140     if ($taper_pid) {
 141         if (waitpid($taper_pid, WNOHANG) == $taper_pid) {
 142             $taper_pid = undef;
 143         }
 144     }
 145 }
 146
 147 sub taper_cmd {
 148     my ($cmd) = @_;
 149
 150     diag(">>> $cmd") if $debug;
 151     print $taper_in "$cmd\n";
 152 }
 153
 154 sub taper_reply {
 155     local $SIG{ALRM} = sub { die "Timeout while waiting for reply\n" };
 156     alarm($taper_reply_timeout);
 157     $last_taper_reply = $taper_out->getline();
 158     alarm(0);
 159
 160     if (!$last_taper_reply) {
 161         die("wrong pid") unless ($taper_pid == waitpid($taper_pid, 0));
 162         my $exit_status = $?;
 163
 164         open(my $fh, "<", $taper_stderr_file) or die("open $taper_stderr_file: $!");
 165         my $stderr = do { local $/; <$fh> };
 166         close($fh);
 167
 168         diag("taper stderr:\n$stderr") if $stderr;
 169         die("taper (pid $taper_pid) died unexpectedly with status $exit_status");
 170     }
 171
 172     # trim trailing whitespace -- C taper outputs an extra ' ' after
 173     # single-word replies
 174     $last_taper_reply =~ s/\s*$//;
 175     diag("<<< $last_taper_reply") if $debug;
 176
 177     return $last_taper_reply;
 178 }
 179
 180 sub check_logs {
 181     my ($expected, $msg) = @_;
 182     my $re;
 183     my $line;
 184
 185     # must contain a pid line at the beginning and end
 186     unshift @$expected, qr/^INFO taper taper pid \d+$/;
 187     push @$expected, qr/^INFO taper pid-done \d+$/;
 188
 189     open(my $logfile, "<", "$CONFIG_DIR/TESTCONF/log/log")
 190         or die("opening log: $!");
 191     my @logfile = grep(/^\S+ taper /, <$logfile>);
 192     close($logfile);
 193
 194     while (@logfile and @$expected) {
 195         my $logline = shift @logfile;
 196         my $expline = shift @$expected;
 197         chomp $logline;
 198         if ($logline !~ $expline) {
 199             like($logline, $expline, $msg);
 200             return;
 201         }
 202     }
 203     if (@logfile) {
 204         fail("$msg (extra trailing log lines)");
 205         return;
 206     }
 207     if (@$expected) {
 208         fail("$msg (logfile ends early)");
 209         diag("first missing line should match ");
 210         diag("".$expected->[0]);
 211         return;
 212     }
 213
 214     pass($msg);
 215 }
 216
 217 sub cleanup_log {
 218     my $logfile = "$CONFIG_DIR/TESTCONF/log/log";
 219     -f $logfile and unlink($logfile);
 220 }
 221
 222 # functions to create dumpfiles
 223
 224 sub write_dumpfile_header_to {
 225     my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
 226
 227     my $hdr = Amanda::Header->new();
 228     $hdr->{'type'} = $Amanda::Header::F_DUMPFILE;
 229     $hdr->{'datestamp'} = $datestamp;
 230     $hdr->{'dumplevel'} = 0;
 231     $hdr->{'compressed'} = 0;
 232     $hdr->{'comp_suffix'} = ".foo";
 233     $hdr->{'name'} = $hostname;
 234     $hdr->{'disk'} = $disk;
 235     $hdr->{'program'} = "INSTALLCHECK";
 236     $hdr = $hdr->to_string(32768,32768);
 237
 238     $fh->syswrite($hdr, 32768);
 239 }
 240
 241 sub write_dumpfile_data_to {
 242     my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
 243
 244     my $bytes_to_write = $size;
 245     my $bufbase = substr((('='x127)."\n".('-'x127)."\n") x 4, 8, -3) . "1K\n";
 246     die length($bufbase) unless length($bufbase) == 1024-8;
 247     my $k = 0;
 248     while ($bytes_to_write > 0) {
 249         my $buf = sprintf("%08x", $k++).$bufbase;
 250         my $written = $fh->syswrite($buf, $bytes_to_write);
 251         if (!defined($written)) {
 252             die "writing: $!" unless $expect_failure;
 253             exit;
 254         }
 255         $bytes_to_write -= $written;
 256     }
 257 }
 258
 259 # make a new holding-like file in test_filename
 260 sub make_holding_file {
 261     my ($size, $hostname, $disk) = @_;
 262     open(my $fh, ">", $test_filename);
 263     write_dumpfile_header_to($fh, $size, $hostname, $disk);
 264     write_dumpfile_data_to($fh, $size, $hostname, $disk);
 265 }
 266
 267 # connect to the given port and write a dumpfile; this *will* create
 268 # zombies, but it's OK -- installchecks aren't daemons.
 269 sub write_to_port {
 270     my ($port_cmd, $size, $hostname, $disk, $expect_error) = @_;
 271
 272     my ($header_port, $data_addr) =
 273         ($last_taper_reply =~ /^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+)/);
 274
 275     # just run this in the child
 276     return unless fork() == 0;
 277
 278     my $sock = IO::Socket::INET->new(
 279         PeerAddr => "127.0.0.1:$header_port",
 280         Proto => "tcp",
 281         ReuseAddr => 1,
 282     );
 283
 284     write_dumpfile_header_to($sock, $size, $hostname, $disk, $expect_error);
 285     close $sock;
 286
 287     $sock = IO::Socket::INET->new(
 288         PeerAddr => $data_addr,
 289         Proto => "tcp",
 290         ReuseAddr => 1,
 291     );
 292
 293     write_dumpfile_data_to($sock, $size, $hostname, $disk, $expect_error);
 294     exit;
 295 }
 296
 297 ########
 298
 299 ##
 300 # A simple, one-part FILE-WRITE
 301 $handle = "11-11111";
 302 $datestamp = "20070102030405";
 303 run_taper(4096, "single-part and multipart FILE-WRITE");
 304 like(taper_reply, qr/^TAPER-OK worker0$/,
 305         "got TAPER-OK") or die;
 306 make_holding_file(1024*1024, "localhost", "/home");
 307 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp \"\" \"\" \"\" \"\" \"\" \"\" \"\" \"\" 12");
 308 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 309         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 310 taper_cmd("START-SCAN worker0 $handle");
 311 taper_cmd("NEW-TAPE worker0 $handle");
 312 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 313         "got proper NEW-TAPE worker0 $handle") or die;
 314 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 1024 "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]"$/,
 315         "got PARTDONE") or die;
 316 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]" "" ""$/,
 317         "got DONE") or die;
 318
 319 ##
 320 # A multipart FILE-WRITE, using the same taper instance
 321 #  (note that the third part is of length 0, and is not logged)
 322
 323 $handle = '11-22222';
 324 make_holding_file(1024*1024, "localhost", "/usr");
 325 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 524288 \"\" \"\" 1 \"\" \"\" \"\" \"\" 512");
 326 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 512 "\[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]"$/,
 327         "got PARTDONE for filenum 2") or die;
 328 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 512 "\[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]"$/,
 329         "got PARTDONE for filenum 3") or die;
 330 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 512\]" "" ""$/,
 331         "got DONE") or die;
 332 taper_cmd("QUIT");
 333 wait_for_exit();
 334
 335 check_logs([
 336     qr(^INFO taper Slot 1 without label can be labeled$),
 337     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 338     qr(^PART taper TESTCONF01 1 localhost /home $datestamp 1/-1 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]$),
 339     qr(^DONE taper localhost /home $datestamp 1 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]$),
 340     qr(^PART taper TESTCONF01 2 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]$),
 341     qr(^PART taper TESTCONF01 3 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]$),
 342     qr(^DONE taper localhost /usr $datestamp 2 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 512\]$),
 343     qr(^INFO taper tape TESTCONF01 kb 2048 fm 4 \[OK\]$),
 344 ], "single-part and multi-part dump logged correctly");
 345
 346 # check out the headers on those files, just to be sure
 347 {
 348     my $dev = Amanda::Device->new("file:" . Installcheck::Run::vtape_dir());
 349     die("bad device: " . $dev->error_or_status()) unless $dev->status == $DEVICE_STATUS_SUCCESS;
 350
 351     $dev->start($ACCESS_READ, undef, undef)
 352         or die("can't start device: " . $dev->error_or_status());
 353
 354     sub is_hdr {
 355         my ($hdr, $expected, $msg) = @_;
 356         my $got = {};
 357         for (keys %$expected) { $got->{$_} = "".$hdr->{$_}; }
 358         if (!is_deeply($got, $expected, $msg)) {
 359             diag("got: " . Dumper($got));
 360         }
 361     }
 362
 363     is_hdr($dev->seek_file(1), {
 364         type => $F_SPLIT_DUMPFILE,
 365         datestamp => $datestamp,
 366         name => 'localhost',
 367         disk => '/home',
 368     }, "header on file 1 is correct");
 369
 370     is_hdr($dev->seek_file(2), {
 371         type => $F_SPLIT_DUMPFILE,
 372         datestamp => $datestamp,
 373         name => 'localhost',
 374         disk => '/usr',
 375         partnum => 1,
 376         totalparts => -1,
 377     }, "header on file 2 is correct");
 378
 379     is_hdr($dev->seek_file(3), {
 380         type => $F_SPLIT_DUMPFILE,
 381         datestamp => $datestamp,
 382         name => 'localhost',
 383         disk => '/usr',
 384         partnum => 2,
 385         totalparts => -1,
 386     }, "header on file 3 is correct");
 387
 388     is_hdr($dev->seek_file(4), {
 389         type => $F_SPLIT_DUMPFILE,
 390         datestamp => $datestamp,
 391         name => 'localhost',
 392         disk => '/usr',
 393         partnum => 3,
 394         totalparts => -1,
 395     }, "header on file 4 is correct");
 396 }
 397
 398 ##
 399 # A PORT-WRITE with no disk buffer
 400
 401 $handle = "11-33333";
 402 $datestamp = "19780615010203";
 403 run_taper(4096, "multipart PORT-WRITE");
 404 like(taper_reply, qr/^TAPER-OK worker0$/,
 405         "got TAPER-OK") or die;
 406 taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 524288 \"\" 393216 1 0 \"\" \"\" 0 AMANDA");
 407 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 408         "got PORT with data address");
 409 write_to_port($last_taper_reply, 63*32768, "localhost", "/var", 0);
 410 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 411         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 412 taper_cmd("START-SCAN worker0 $handle");
 413 taper_cmd("NEW-TAPE worker0 $handle");
 414 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 415         "got proper NEW-TAPE worker0 $handle") or die;
 416 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
 417         "got PARTDONE for filenum 1") or die;
 418 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
 419         "got PARTDONE for filenum 2") or die;
 420 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
 421         "got PARTDONE for filenum 3") or die;
 422 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
 423         "got PARTDONE for filenum 4") or die;
 424 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 5 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
 425         "got PARTDONE for filenum 5") or die;
 426 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 6 96 "\[sec [\d.]+ bytes 98304 kps [\d.]+\]"$/,
 427         "got PARTDONE for filenum 6") or die;
 428 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 429         "got DUMPER-STATUS request") or die;
 430 taper_cmd("DONE worker0 $handle 712");
 431 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 2064384 kps [\d.]+ orig-kb 712\]" "" ""$/,
 432         "got DONE") or die;
 433 taper_cmd("QUIT");
 434 wait_for_exit();
 435
 436 check_logs([
 437     qr(^INFO taper Slot 1 without label can be labeled$),
 438     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 439     qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
 440     qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
 441     qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
 442     qr(^PART taper TESTCONF01 4 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
 443     qr(^PART taper TESTCONF01 5 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
 444     qr(^PART taper TESTCONF01 6 localhost /var $datestamp 6/-1 0 \[sec [\d.]+ bytes 98304 kps [\d.]+\]$),
 445     qr(^DONE taper localhost /var $datestamp 6 0 \[sec [\d.]+ bytes 2064384 kps [\d.]+ orig-kb 712\]$),
 446     qr(^INFO taper tape TESTCONF01 kb 2016 fm 6 \[OK\]$),
 447 ], "multipart PORT-WRITE logged correctly");
 448
 449 ##
 450 # Test NO-NEW-TAPE
 451
 452 $handle = "11-44444";
 453 $datestamp = "19411207000000";
 454 run_taper(4096, "testing NO-NEW-TAPE from the driver on 1st request");
 455 like(taper_reply, qr/^TAPER-OK worker0$/,
 456         "got TAPER-OK") or die;
 457 make_holding_file(1024*1024, "localhost", "/home");
 458 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp 0 \"\" 0 1 0 \"\" \"\" 0 912");
 459 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 460         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 461 taper_cmd("NO-NEW-TAPE worker0 $handle sorry");
 462 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
 463         "got FAILED") or die;
 464 taper_cmd("QUIT");
 465 wait_for_exit();
 466
 467 check_logs([
 468     qr(^INFO taper Slot 1 without label can be labeled$),
 469     qr(^ERROR taper no-tape config \[sorry\]$),
 470     qr(^FAIL taper localhost /home $datestamp 0 config sorry$),
 471 ], "NO-NEW-TAPE logged correctly");
 472
 473 ##
 474 # Test retrying on EOT (via PORT-WRITE with a mem cache)
 475
 476 $handle = "11-55555";
 477 $datestamp = "19750711095836";
 478 run_taper(1024, "PORT-WRITE retry on EOT (mem cache)");
 479 like(taper_reply, qr/^TAPER-OK worker0$/,
 480         "got TAPER-OK") or die;
 481 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"\" 786432 1 0 \"\" \"\" 0 AMANDA");
 482 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 483         "got PORT with data address");
 484 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
 485 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 486         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 487 taper_cmd("START-SCAN worker0 $handle");
 488 taper_cmd("NEW-TAPE worker0 $handle");
 489 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 490         "got proper NEW-TAPE worker0 $handle") or die;
 491 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+\]"$/,
 492         "got PARTDONE for filenum 1") or die;
 493 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 494         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 495 taper_cmd("START-SCAN worker0 $handle");
 496 taper_cmd("NEW-TAPE worker0 $handle");
 497 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 498         "got proper NEW-TAPE worker0 $handle") or die;
 499 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+\]"$/,
 500         "got PARTDONE for filenum 1 on second tape") or die;
 501 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ bytes 3072 kps [\d.]+\]"$/,
 502         "got PARTDONE for filenum 2 on second tape") or die;
 503 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 504         "got DUMPER-STATUS request") or die;
 505 taper_cmd("DONE worker0 $handle 1012");
 506 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1012\]" "" ""$/,
 507         "got DONE") or die;
 508 taper_cmd("QUIT");
 509 wait_for_exit();
 510
 511 check_logs([
 512     qr(^INFO taper Slot 1 without label can be labeled$),
 513     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 514     qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+\]$),
 515     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ bytes 163840 kps [\d.]+\] "No space left on device"$),
 516     qr(^INFO taper Will request retry of failed split part\.$),
 517     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 518     qr(^INFO taper Slot 2 without label can be labeled$),
 519     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 520     qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+\]$),
 521     qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ bytes 3072 kps [\d.]+\]$),
 522     qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1012\]$),
 523     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 524 ], "multivolume PORT-WRITE logged correctly");
 525
 526 ##
 527 # Test retrying on EOT (via FILE-WRITE)
 528
 529 $handle = "11-66666";
 530 $datestamp = "19470815000000";
 531 run_taper(1024, "FILE-WRITE retry on EOT");
 532 like(taper_reply, qr/^TAPER-OK worker0$/,
 533         "got TAPER-OK") or die;
 534 make_holding_file(1575936, "localhost", "/usr");
 535 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp \"\" \"\" \"\" 1 786432 \"\" \"\" \"\" 1112");
 536 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 537         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 538 taper_cmd("START-SCAN worker0 $handle");
 539 taper_cmd("NEW-TAPE worker0 $handle");
 540 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 541         "got proper NEW-TAPE worker0 $handle") or die;
 542 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+ orig-kb 1112\]"$/,
 543         "got PARTDONE for filenum 1") or die;
 544 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 545         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 546 taper_cmd("START-SCAN worker0 $handle");
 547 taper_cmd("NEW-TAPE worker0 $handle");
 548 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 549         "got proper NEW-TAPE worker0 $handle") or die;
 550 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+ orig-kb 1112\]"$/,
 551         "got PARTDONE for filenum 1 on second tape") or die;
 552 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ bytes 3072 kps [\d.]+ orig-kb 1112\]"$/,
 553         "got PARTDONE for filenum 2 on second tape") or die;
 554 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1112\]" "" ""$/,
 555         "got DONE") or die;
 556 taper_cmd("QUIT");
 557 wait_for_exit();
 558
 559 check_logs([
 560     qr(^INFO taper Slot 1 without label can be labeled$),
 561     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 562     qr(^PART taper TESTCONF01 1 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+ orig-kb 1112\]$),
 563     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ bytes 163840 kps [\d.]+ orig-kb 1112\] "No space left on device"$),
 564     qr(^INFO taper Will request retry of failed split part\.$),
 565     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 566     qr(^INFO taper Slot 2 without label can be labeled$),
 567     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 568     qr(^PART taper TESTCONF02 1 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+ orig-kb 1112\]$),
 569     qr(^PART taper TESTCONF02 2 localhost /usr $datestamp 3/-1 0 \[sec [\d.]+ bytes 3072 kps [\d.]+ orig-kb 1112\]$),
 570     qr(^DONE taper localhost /usr $datestamp 3 0 \[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1112\]$),
 571     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 572 ], "multivolume FILE-WRITE logged correctly");
 573
 574 ##
 575 # Test retrying on EOT (via PORT-WRITE with a disk cache)
 576
 577 $handle = "11-77777";
 578 $datestamp = "20090427212500";
 579 run_taper(1024, "PORT-WRITE retry on EOT (disk cache)");
 580 like(taper_reply, qr/^TAPER-OK worker0$/,
 581         "got TAPER-OK") or die;
 582 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"$Installcheck::TMP\" 786432 1 0 \"\" \"\" 0 AMANDA");
 583 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 584         "got PORT with data address");
 585 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
 586 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 587         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 588 taper_cmd("START-SCAN worker0 $handle");
 589 taper_cmd("NEW-TAPE worker0 $handle");
 590 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 591         "got proper NEW-TAPE worker0 $handle") or die;
 592 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+\]"$/,
 593         "got PARTDONE for filenum 1") or die;
 594 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 595         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 596 taper_cmd("START-SCAN worker0 $handle");
 597 taper_cmd("NEW-TAPE worker0 $handle");
 598 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 599         "got proper NEW-TAPE worker0 $handle") or die;
 600 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ bytes 786432 kps [\d.]+\]"$/,
 601         "got PARTDONE for filenum 1 on second tape") or die;
 602 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ bytes 3072 kps [\d.]+\]"$/,
 603         "got PARTDONE for filenum 2 on second tape") or die;
 604 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 605         "got DUMPER-STATUS request") or die;
 606 taper_cmd("DONE worker0 $handle 1212");
 607 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1212\]" "" ""$/,
 608         "got DONE") or die;
 609 taper_cmd("QUIT");
 610 wait_for_exit();
 611
 612 check_logs([
 613     qr(^INFO taper Slot 1 without label can be labeled$),
 614     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 615     qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+\]$),
 616     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ bytes 163840 kps [\d.]+\] "No space left on device"$),
 617     qr(^INFO taper Will request retry of failed split part\.$),
 618     qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
 619     qr(^INFO taper Slot 2 without label can be labeled$),
 620     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 621     qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ bytes 786432 kps [\d.]+\]$),
 622     qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ bytes 3072 kps [\d.]+\]$),
 623     qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ bytes 1575936 kps [\d.]+ orig-kb 1212\]$),
 624     qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
 625 ], "multivolume PORT-WRITE (disk cache) logged correctly");
 626
 627 ##
 628 # Test failure on EOT (via PORT-WRITE with no cache), and a new try on the
 629 # next tape.
 630
 631 $handle = "11-88888";
 632 $datestamp = "20090424173000";
 633 run_taper(1024, "PORT-WRITE failure on EOT (no cache)");
 634 like(taper_reply, qr/^TAPER-OK worker0$/,
 635         "got TAPER-OK") or die;
 636 taper_cmd("PORT-WRITE worker0 $handle localhost /var/log 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
 637 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 638         "got PORT with data address");
 639 write_to_port($last_taper_reply, 1575936, "localhost", "/var/log", 1);
 640 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 641         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 642 taper_cmd("START-SCAN worker0 $handle");
 643 taper_cmd("NEW-TAPE worker0 $handle");
 644 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 645         "got proper NEW-TAPE worker0 $handle") or die;
 646 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ bytes 0 kps [\d.]+\]" "" "No space left on device, splitting not enabled"$/,
 647         "got PARTIAL") or die;
 648 # retry on the next tape
 649 $handle = "11-88899";
 650 taper_cmd("PORT-WRITE worker0 $handle localhost /boot 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
 651 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 652         "got PORT with data address");
 653 write_to_port($last_taper_reply, 65536, "localhost", "/boot", 0);
 654 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 655         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 656 taper_cmd("START-SCAN worker0 $handle");
 657 taper_cmd("NEW-TAPE worker0 $handle");
 658 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 659         "got proper NEW-TAPE worker0 $handle") or die;
 660 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 64 "\[sec [\d.]+ bytes 65536 kps [\d.]+\]"$/,
 661         "got PARTDONE for filenum 1 on second tape") or die;
 662 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 663         "got DUMPER-STATUS request") or die;
 664 taper_cmd("DONE worker0 $handle 64");
 665 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 65536 kps [\d.]+ orig-kb 64\]" "" ""$/,
 666         "got DONE") or die;
 667 taper_cmd("QUIT");
 668 wait_for_exit();
 669
 670 check_logs([
 671     qr(^INFO taper Slot 1 without label can be labeled$),
 672     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 673     qr(^PARTPARTIAL taper TESTCONF01 1 localhost /var/log $datestamp 1/-1 0 \[sec [\d.]+ bytes 983040 kps [\d.]+\] "No space left on device"$),
 674     qr(^PARTIAL taper localhost /var/log $datestamp 1 0 \[sec [\d.]+ bytes 0 kps [\d.]+\] "No space left on device, splitting not enabled"$),
 675     qr(^INFO taper tape TESTCONF01 kb 0 fm 1 \[OK\]$),
 676     qr(^INFO taper Slot 2 without label can be labeled$),
 677     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 678     qr(^PART taper TESTCONF02 1 localhost /boot $datestamp 1/-1 0 \[sec [\d.]+ bytes 65536 kps [\d.]+\]$),
 679     qr(^DONE taper localhost /boot $datestamp 1 0 \[sec [\d.]+ bytes 65536 kps [\d.]+ orig-kb 64\]$),
 680     qr(^INFO taper tape TESTCONF02 kb 64 fm 1 \[OK\]$),
 681 ], "failure on EOT (no cache) with subsequent dump logged correctly");
 682
 683 ##
 684 # Test running out of tapes (second REQUEST-NEW-TAPE fails)
 685
 686 $handle = "11-99999";
 687 $datestamp = "20100101000000";
 688 run_taper(512, "FILE-WRITE runs out of tapes");
 689 like(taper_reply, qr/^TAPER-OK worker0$/,
 690         "got TAPER-OK") or die;
 691 make_holding_file(512*1024, "localhost", "/music");
 692 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /music 0 $datestamp \"\" \"\" \"\" 1 262144 \"none\" \"\" 10240 1312");
 693 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 694         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 695 taper_cmd("START-SCAN worker0 $handle");
 696 taper_cmd("NEW-TAPE worker0 $handle");
 697 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 698         "got proper NEW-TAPE worker0 $handle") or die;
 699 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1312\]"$/,
 700         "got PARTDONE for filenum 1 on first tape") or die;
 701 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 702         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 703 taper_cmd("NO-NEW-TAPE worker0 $handle \"that's enough\"");
 704 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1312\]" "" "that's enough"$/,
 705         "got PARTIAL") or die;
 706 taper_cmd("QUIT");
 707 wait_for_exit();
 708
 709 check_logs([
 710     qr(^INFO taper Slot 1 without label can be labeled$),
 711     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 712     qr(^PART taper TESTCONF01 1 localhost /music $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1312\]$),
 713     qr(^PARTPARTIAL taper TESTCONF01 2 localhost /music $datestamp 2/-1 0 \[sec [\d.]+ bytes 163840 kps [\d.]+ orig-kb 1312\] "No space left on device"$),
 714     qr(^INFO taper Will request retry of failed split part\.$),
 715     qr(^INFO taper tape TESTCONF01 kb 256 fm 2 \[OK\]$),
 716     qr(^ERROR taper no-tape config \[that's enough\]$),
 717     qr(^PARTIAL taper localhost /music $datestamp 2 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1312\] "that's enough"$),
 718 ], "running out of tapes (simulating runtapes=1) logged correctly");
 719
 720 ##
 721 # A PORT-WRITE with no disk buffer
 722
 723 $handle = "22-00000";
 724 $datestamp = "20200202222222";
 725 run_taper(4096, "multipart PORT-WRITE");
 726 like(taper_reply, qr/^TAPER-OK worker0$/,
 727         "got TAPER-OK") or die;
 728 taper_cmd("PORT-WRITE worker0 $handle localhost /sbin 0 $datestamp 999999 \"\" 655360 1 \"\" \"\" \"\" \"\" AMANDA");
 729 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
 730         "got PORT with data address");
 731 write_to_port($last_taper_reply, 63*32768, "localhost", "/sbin", 0);
 732 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 733         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 734 taper_cmd("START-SCAN worker0 $handle");
 735 taper_cmd("NEW-TAPE worker0 $handle");
 736 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 737         "got proper NEW-TAPE worker0 $handle") or die;
 738 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 640 "\[sec [\d.]+ bytes 655360 kps [\d.]+\]"$/,
 739         "got PARTDONE for filenum 1") or die;
 740 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 640 "\[sec [\d.]+ bytes 655360 kps [\d.]+\]"$/,
 741         "got PARTDONE for filenum 2") or die;
 742 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 640 "\[sec [\d.]+ bytes 655360 kps [\d.]+\]"$/,
 743         "got PARTDONE for filenum 3") or die;
 744 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 96 "\[sec [\d.]+ bytes 98304 kps [\d.]+\]"$/,
 745         "got PARTDONE for filenum 4") or die;
 746 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
 747         "got DUMPER-STATUS request") or die;
 748 taper_cmd("FAILED worker0 $handle");
 749 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 2064384 kps [\d.]+\]" "" ""$/,
 750         "got DONE") or die;
 751 taper_cmd("QUIT");
 752 wait_for_exit();
 753
 754 check_logs([
 755     qr(^INFO taper Slot 1 without label can be labeled$),
 756     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 757     qr(^PART taper TESTCONF01 1 localhost /sbin $datestamp 1/-1 0 \[sec [\d.]+ bytes 655360 kps [\d.]+\]$),
 758     qr(^PART taper TESTCONF01 2 localhost /sbin $datestamp 2/-1 0 \[sec [\d.]+ bytes 655360 kps [\d.]+\]$),
 759     qr(^PART taper TESTCONF01 3 localhost /sbin $datestamp 3/-1 0 \[sec [\d.]+ bytes 655360 kps [\d.]+\]$),
 760     qr(^PART taper TESTCONF01 4 localhost /sbin $datestamp 4/-1 0 \[sec [\d.]+ bytes 98304 kps [\d.]+\]$),
 761     qr(^PARTIAL taper localhost /sbin $datestamp 4 0 \[sec [\d.]+ bytes 2064384 kps [\d.]+\]$), # note no error message
 762     qr(^INFO taper tape TESTCONF01 kb 2016 fm 4 \[OK\]$),
 763 ], "DUMPER_STATUS => FAILED logged correctly");
 764
 765 ##
 766 # Test a sequence of writes to the same set of tapes
 767
 768 $handle = "33-11111";
 769 $datestamp = "20090101010000";
 770 run_taper(1024, "first in a sequence");
 771 like(taper_reply, qr/^TAPER-OK worker0$/,
 772         "got TAPER-OK") or die;
 773 make_holding_file(500000, "localhost", "/u01");
 774 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1412");
 775 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 776         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 777 taper_cmd("START-SCAN worker0 $handle");
 778 taper_cmd("NEW-TAPE worker0 $handle");
 779 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 780         "got proper NEW-TAPE worker0 $handle") or die;
 781 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1412\]"$/,
 782         "got PARTDONE for filenum 1") or die;
 783 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 232 "\[sec [\d.]+ bytes 237856 kps [\d.]+ orig-kb 1412\]"$/,
 784         "got PARTDONE for filenum 2") or die;
 785 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 500000 kps [\d.]+ orig-kb 1412\]" "" ""$/,
 786         "got DONE") or die;
 787 $handle = "33-22222";
 788 make_holding_file(614400, "localhost", "/u02");
 789 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1512");
 790 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]"$/,
 791         "got PARTDONE for filenum 3") or die;
 792 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 793         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 794 taper_cmd("START-SCAN worker0 $handle");
 795 taper_cmd("NEW-TAPE worker0 $handle");
 796 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
 797         "got proper NEW-TAPE worker0 $handle") or die;
 798 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]"$/,
 799         "got PARTDONE for filenum 1 on second tape") or die;
 800 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1512\]"$/,
 801         "got PARTDONE for filenum 2 on second tape") or die;
 802 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1512\]" "" ""$/,
 803         "got DONE") or die;
 804 taper_cmd("QUIT");
 805 wait_for_exit();
 806
 807 check_logs([
 808     qr(^INFO taper Slot 1 without label can be labeled$),
 809     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 810     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1412\]$),
 811     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 237856 kps [\d.]+ orig-kb 1412\]$),
 812     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 500000 kps [\d.]+ orig-kb 1412\]$),
 813     qr(^PART taper TESTCONF01 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]$),
 814     qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 98304 kps [\d.]+ orig-kb 1512\] "No space left on device"$),
 815     qr(^INFO taper Will request retry of failed split part\.$),
 816     qr(^INFO taper tape TESTCONF01 kb 744 fm 4 \[OK\]$),
 817     qr(^INFO taper Slot 2 without label can be labeled$),
 818     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 819     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]$),
 820     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1512\]$),
 821     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1512\]$),
 822     qr(^INFO taper tape TESTCONF02 kb 344 fm 2 \[OK\]$),
 823 ], "first taper invocation in sequence logged correctly");
 824 cleanup_log();
 825
 826 $handle = "33-33333";
 827 $datestamp = "20090202020000";
 828 run_taper(1024, "second in a sequence", keep_config => 1);
 829 like(taper_reply, qr/^TAPER-OK worker0$/,
 830         "got TAPER-OK") or die;
 831 make_holding_file(300000, "localhost", "/u01");
 832 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
 833 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 834         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 835 taper_cmd("START-SCAN worker0 $handle");
 836 taper_cmd("NEW-TAPE worker0 $handle");
 837 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF03$/,
 838         "got proper NEW-TAPE worker0 $handle") or die;
 839 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
 840         "got PARTDONE for filenum 1") or die;
 841 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 2 36 "\[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]"$/,
 842         "got PARTDONE for filenum 2") or die;
 843 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]" "" ""$/,
 844         "got DONE") or die;
 845 $handle = "33-44444";
 846 make_holding_file(614400, "localhost", "/u02");
 847 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
 848 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 3 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
 849         "got PARTDONE for filenum 3") or die;
 850 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 4 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
 851         "got PARTDONE for filenum 4") or die;
 852 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 853         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 854 taper_cmd("START-SCAN worker0 $handle");
 855 taper_cmd("NEW-TAPE worker0 $handle");
 856 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
 857         "got proper NEW-TAPE worker0 $handle") or die;
 858 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]"$/,
 859         "got PARTDONE for filenum 1 on second tape") or die;
 860 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]" "" ""$/,
 861         "got DONE") or die;
 862 taper_cmd("QUIT");
 863 wait_for_exit();
 864
 865 check_logs([
 866     qr(^INFO taper Slot 2 with label TESTCONF02 is not reusable$),
 867     qr(^INFO taper Slot 3 without label can be labeled$),
 868     qr(^START taper datestamp $datestamp label TESTCONF03 tape 1$),
 869     qr(^PART taper TESTCONF03 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
 870     qr(^PART taper TESTCONF03 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]$),
 871     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]$),
 872     qr(^PART taper TESTCONF03 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
 873     qr(^PART taper TESTCONF03 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
 874     qr(^PARTPARTIAL taper TESTCONF03 5 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 0 kps [\d.]+ orig-kb 1712\] "No space left on device"$),
 875     qr(^INFO taper Will request retry of failed split part\.$),
 876     qr(^INFO taper tape TESTCONF03 kb 804 fm 5 \[OK\]$),
 877     qr(^INFO taper Slot 1 with label TESTCONF01 is usable$),
 878     qr(^START taper datestamp $datestamp label TESTCONF01 tape 2$),
 879     qr(^PART taper TESTCONF01 1 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]$),
 880     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]$),
 881     qr(^INFO taper tape TESTCONF01 kb 88 fm 1 \[OK\]$),
 882 ], "second taper invocation in sequence logged correctly");
 883 cleanup_log();
 884
 885 ##
 886 # test failure to overwrite a tape label
 887
 888 $handle = "33-55555";
 889 $datestamp = "20090303030000";
 890 run_taper(1024, "failure to overwrite a volume", keep_config => 1);
 891 like(taper_reply, qr/^TAPER-OK worker0$/,
 892         "got TAPER-OK") or die;
 893 make_holding_file(32768, "localhost", "/u03");
 894 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u03 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1812");
 895 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 896         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 897 # we've secretly replaced the tape in slot 1 with a read-only tape.. let's see
 898 # if anyone can tell the difference!
 899 chmod(0555, Installcheck::Run::vtape_dir(2));
 900 taper_cmd("START-SCAN worker0 $handle");
 901 taper_cmd("NEW-TAPE worker0 $handle");
 902 # NO-NEW-TAPE indicates it did *not* overwrite the tape
 903 like(taper_reply, qr/^NO-NEW-TAPE $handle$/,
 904         "got proper NO-NEW-TAPE worker0 $handle"); # no "die" here, so we can restore perms
 905 chmod(0755, Installcheck::Run::vtape_dir(2));
 906 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
 907         "got REQUEST-NEW-TAPE worker0 $handle") or die;
 908 taper_cmd("NO-NEW-TAPE worker0 $handle \"sorry\"");
 909 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
 910         "got FAILED") or die;
 911 taper_cmd("QUIT");
 912 wait_for_exit();
 913
 914 # (logs aren't that interesting here - filled with VFS-specific error messages)
 915
 916 # TODO: simulate an "erased" tape, to which taper should reply with "NEW-TAPE worker0 $handle" and
 917 # immediately REQUEST-NEW-TAPE.  I can't see a way to make the VFS device erase a
 918 # volume without start_device succeeding.
 919
 920 ##
 921 # A run with a bogus tapedev/tpchanger
 922 $handle = "44-11111";
 923 $datestamp = "20070102030405";
 924 run_taper(4096, "no tapedev", notapedev => 1);
 925 like(taper_reply, qr/^TAPE-ERROR SETUP "You must specify one of 'tapedev' or 'tpchanger'"$/,
 926         "got TAPE-ERROR") or die;
 927 wait_for_exit();
 928
 929 ##
 930 # A run with 2 workers
 931 my $handle0 = "66-00000";
 932 my $handle1 = "66-11111";
 933 $datestamp = "20090202020000";
 934 run_taper(1024, "with 2 workers", new_vtapes => 1);
 935 like(taper_reply, qr/^TAPER-OK worker0$/,
 936         "got TAPER-OK") or die;
 937 taper_cmd("START-TAPER worker1 $datestamp");
 938 like(taper_reply, qr/^TAPER-OK worker1$/,
 939        "got TAPER-OK") or die;
 940 make_holding_file(300000, "localhost", "/u01");
 941 taper_cmd("FILE-WRITE worker0 $handle0 \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
 942 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle0$/,
 943         "got REQUEST-NEW-TAPE worker0 $handle0") or die;
 944 taper_cmd("START-SCAN worker0 $handle0");
 945 taper_cmd("NEW-TAPE worker0 $handle0");
 946 like(taper_reply, qr/^NEW-TAPE $handle0 TESTCONF01$/,
 947         "got proper NEW-TAPE worker0 $handle0") or die;
 948 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
 949         "got PARTDONE for filenum 1") or die;
 950 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 2 36 "\[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]"$/,
 951         "got PARTDONE for filenum 2") or die;
 952 like(taper_reply, qr/^DONE $handle0 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]" "" ""$/,
 953         "got DONE") or die;
 954 make_holding_file(614400, "localhost", "/u02");
 955 taper_cmd("FILE-WRITE worker1 $handle1 \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
 956 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle1$/,
 957         "got REQUEST-NEW-TAPE worker1 $handle1") or die;
 958 taper_cmd("START-SCAN worker1 $handle1");
 959 taper_cmd("NEW-TAPE worker1 $handle1");
 960 like(taper_reply, qr/^NEW-TAPE $handle1 TESTCONF02$/,
 961         "got proper NEW-TAPE worker1 $handle1") or die;
 962 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
 963         "got PARTDONE for filenum 1 on second tape") or die;
 964 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 2 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
 965         "got PARTDONE for filenum 2 on second tape") or die;
 966 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 3 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]"$/,
 967         "got PARTDONE for filenum 3 on second tape") or die;
 968 like(taper_reply, qr/^DONE $handle1 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]" "" ""$/,
 969         "got DONE") or die;
 970 taper_cmd("QUIT");
 971 wait_for_exit();
 972
 973 check_logs([
 974     qr(^INFO taper Slot 1 without label can be labeled$),
 975     qr(^INFO taper Slot 2 without label can be labeled$),
 976     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
 977     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
 978     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]$),
 979     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]$),
 980     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
 981     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
 982     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
 983     qr(^PART taper TESTCONF02 3 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]$),
 984     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]$),
 985     qr(^INFO taper tape TESTCONF01 kb 292 fm 2 \[OK\]$),
 986     qr(^INFO taper tape TESTCONF02 kb 600 fm 3 \[OK\]$),
 987 ], "two workers logged correctly");
 988 cleanup_log();
 989
 990 ##
 991 # A run with 2 workers and a take_scribe
 992 $handle = "66-22222";
 993 $datestamp = "20090202020000";
 994 run_taper(1024, "with 2 workers and a take_scribe", new_vtapes => 1);
 995 like(taper_reply, qr/^TAPER-OK worker0$/,
 996         "got TAPER-OK") or die;
 997 taper_cmd("START-TAPER worker1 $datestamp");
 998 like(taper_reply, qr/^TAPER-OK worker1$/,
 999         "got TAPER-OK") or die;
1000 make_holding_file(1000000, "localhost", "/u01");
1001 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
1002 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1003         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1004 taper_cmd("START-SCAN worker0 $handle");
1005 taper_cmd("NEW-TAPE worker0 $handle");
1006 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1007         "got proper NEW-TAPE worker0 $handle") or die;
1008 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
1009         "got PARTDONE for filenum 1") or die;
1010 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
1011         "got PARTDONE for filenum 2") or die;
1012 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
1013         "got PARTDONE for filenum 3") or die;
1014 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1015         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1016 taper_cmd("TAKE-SCRIBE-FROM worker0 $handle worker1");
1017 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1018         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1019 taper_cmd("START-SCAN worker0 $handle");
1020 taper_cmd("NEW-TAPE worker0 $handle");
1021 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1022         "got proper NEW-TAPE worker0 $handle") or die;
1023 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 208 "\[sec [\d.]+ bytes 213568 kps [\d.]+ orig-kb 1612\]"$/,
1024         "got PARTDONE for filenum 4") or die;
1025 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1000000 kps [\d.]+ orig-kb 1612\]" "" ""$/,
1026         "got DONE") or die;
1027 taper_cmd("QUIT");
1028 wait_for_exit();
1029
1030 check_logs([
1031     qr(^INFO taper Slot 1 without label can be labeled$),
1032     qr(^INFO taper Slot 2 without label can be labeled$),
1033     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1034     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
1035     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
1036     qr(^PART taper TESTCONF01 3 localhost /u01 $datestamp 3/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
1037     qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ bytes 98304 kps [\d.]+ orig-kb 1612\] \"No space left on device\"$),
1038     qr(^INFO taper Will request retry of failed split part.$),
1039     qr(^INFO taper tape TESTCONF01 kb 768 fm 4 \[OK\]$),
1040     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1041     qr(^PART taper TESTCONF02 1 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ bytes 213568 kps [\d.]+ orig-kb 1612\]$),
1042     qr(^DONE taper localhost /u01 $datestamp 4 0 \[sec [\d.]+ bytes 1000000 kps [\d.]+ orig-kb 1612\]$),
1043     qr(^INFO taper tape TESTCONF02 kb 208 fm 1 \[OK\]$),
1044 ], "TAKE-SCRIBE logged correctly");
1045 cleanup_log();
1046
1047 ##
1048 # Test with NDMP device (DirectTCP)
1049
1050 SKIP : {
1051     skip "not built with NDMP", 33 unless Amanda::Util::built_with_component("ndmp");
1052
1053     my $ndmp = Installcheck::Mock::NdmpServer->new(tape_limit => 1024*1024);
1054     my $ndmp_port = $ndmp->{'port'};
1055     my $drive = $ndmp->{'drive'};
1056
1057     $handle = "55-11111";
1058     $datestamp = "19780615010305";
1059     run_taper(4096, "multipart directtcp PORT-WRITE",
1060         ndmp_server => $ndmp);
1061     like(taper_reply, qr/^TAPER-OK worker0$/,
1062             "got TAPER-OK") or die;
1063     # note that, with the addition of the new splitting params, this does the "sensible"
1064     # thing and uses the tape_splitsize, not the fallback_splitsize (this is a change from
1065     # Amanda-3.1)
1066     taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 393216 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1067     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1068             "got PORT with data address");
1069     write_to_port($last_taper_reply, 1230*1024, "localhost", "/var", 0);
1070     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1071             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1072     taper_cmd("START-SCAN worker0 $handle");
1073     taper_cmd("NEW-TAPE worker0 $handle");
1074     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1075             "got proper NEW-TAPE worker0 $handle") or die;
1076     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
1077             "got PARTDONE for part 1") or die;
1078     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
1079             "got PARTDONE for part 2") or die;
1080     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 64 "\[sec [\d.]+ bytes 65536 kps [\d.]+\]"$/,
1081             "got PARTDONE for part 3 (short part)") or die;
1082     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1083             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1084     taper_cmd("START-SCAN worker0 $handle");
1085     taper_cmd("NEW-TAPE worker0 $handle");
1086     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1087             "got proper NEW-TAPE worker0 $handle") or die;
1088     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
1089             "got PARTDONE for part 4") or die;
1090     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 32 "\[sec [\d.]+ bytes 32768 kps [\d.]+\]"$/,
1091             "got PARTDONE for part 5") or die;
1092     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1093             "got DUMPER-STATUS request") or die;
1094     taper_cmd("DONE worker0 $handle 1912");
1095     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1277952 kps [\d.]+ orig-kb 1912\]" "" ""$/,
1096             "got DONE") or die;
1097     $handle = "55-22222";
1098     taper_cmd("PORT-WRITE worker0 $handle localhost /etc 0 $datestamp 524288 \"\" 393216 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1099     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1100             "got PORT with data address");
1101     write_to_port($last_taper_reply, 300*1024, "localhost", "/etc", 0);
1102     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 3 320 "\[sec [\d.]+ bytes 327680 kps [\d.]+\]"$/,
1103             "got PARTDONE for part 1") or die;
1104     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1105             "got DUMPER-STATUS request") or die;
1106     taper_cmd("DONE worker0 $handle 2012");
1107     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 327680 kps [\d.]+ orig-kb 2012\]" "" ""$/,
1108             "got DONE") or die;
1109     taper_cmd("QUIT");
1110     wait_for_exit();
1111
1112     check_logs([
1113         qr(^INFO taper Slot 3 without label can be labeled$),
1114         qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1115         qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
1116         qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
1117         qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ bytes 65536 kps [\d.]+\]$),
1118         # note no "Will retry.."
1119         qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1120         qr(^INFO taper Slot 4 without label can be labeled$),
1121         qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1122         qr(^PART taper TESTCONF02 1 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
1123         qr(^PART taper TESTCONF02 2 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ bytes 32768 kps [\d.]+\]$),
1124         qr(^DONE taper localhost /var $datestamp 5 0 \[sec [\d.]+ bytes 1277952 kps [\d.]+ orig-kb 1912\]$),
1125         qr(^PART taper TESTCONF02 3 localhost /etc $datestamp 1/-1 0 \[sec [\d.]+ bytes 327680 kps [\d.]+\]$),
1126         qr(^DONE taper localhost /etc $datestamp 1 0 \[sec [\d.]+ bytes 327680 kps [\d.]+ orig-kb 2012\]$),
1127         qr(^INFO taper tape TESTCONF02 kb 736 fm 3 \[OK\]$),
1128     ], "multipart directtcp PORT-WRITE logged correctly");
1129
1130     $handle = "55-33333";
1131     $datestamp = "19780615010305";
1132     run_taper(4096, "multipart directtcp PORT-WRITE, with a zero-byte part",
1133         ndmp_server => $ndmp);
1134     like(taper_reply, qr/^TAPER-OK worker0$/,
1135             "got TAPER-OK") or die;
1136     # use a different part size this time, to hit EOM "on the head"
1137     taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 425984 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1138     like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1139             "got PORT with data address");
1140     write_to_port($last_taper_reply, 1632*1024, "localhost", "/var", 0);
1141     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1142             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1143     taper_cmd("START-SCAN worker0 $handle");
1144     taper_cmd("NEW-TAPE worker0 $handle");
1145     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1146             "got proper NEW-TAPE worker0 $handle") or die;
1147     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 416 "\[sec [\d.]+ bytes 425984 kps [\d.]+\]"$/,
1148             "got PARTDONE for part 1") or die;
1149     like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 416 "\[sec [\d.]+ bytes 425984 kps [\d.]+\]"$/,
1150             "got PARTDONE for part 2") or die;
1151     # note: zero-byte part is not reported as PARTDONE
1152     like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1153             "got REQUEST-NEW-TAPE worker0 $handle") or die;
1154     taper_cmd("START-SCAN worker0 $handle");
1155     taper_cmd("NEW-TAPE worker0 $handle");
1156     like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1157             "got proper NEW-TAPE worker0 $handle") or die;
1158     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 416 "\[sec [\d.]+ bytes 425984 kps [\d.]+\]"$/,
1159             "got PARTDONE for part 3") or die;
1160     like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 384 "\[sec [\d.]+ bytes 393216 kps [\d.]+\]"$/,
1161             "got PARTDONE for part 4") or die;
1162     like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1163             "got DUMPER-STATUS request") or die;
1164     taper_cmd("DONE worker0 $handle 2112");
1165     like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1671168 kps [\d.]+ orig-kb 2112\]" "" ""$/,
1166             "got DONE") or die;
1167     taper_cmd("QUIT");
1168     wait_for_exit();
1169
1170     check_logs([
1171         qr(^INFO taper Slot 3 without label can be labeled$),
1172         qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1173         qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ bytes 425984 kps [\d.]+\]$),
1174         qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ bytes 425984 kps [\d.]+\]$),
1175         # Note: zero-byte part is not logged, but is counted in this INFO line's 'fm' field
1176         qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1177         qr(^INFO taper Slot 4 without label can be labeled$),
1178         qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1179         qr(^PART taper TESTCONF02 1 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ bytes 425984 kps [\d.]+\]$),
1180         qr(^PART taper TESTCONF02 2 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ bytes 393216 kps [\d.]+\]$),
1181         qr(^DONE taper localhost /var $datestamp 4 0 \[sec [\d.]+ bytes 1671168 kps [\d.]+ orig-kb 2112\]$),
1182         qr(^INFO taper tape TESTCONF02 kb 800 fm 2 \[OK\]$),
1183     ], "multipart directtcp PORT-WRITE with a zero-byte part logged correctly");
1184     cleanup_log();
1185
1186     $ndmp->cleanup();
1187 } # end of ndmp SKIP
1188
1189 ##
1190 # A run without LEOM and without allow-split
1191 $handle = "77-11111";
1192 $datestamp = "20090302020000";
1193 run_taper(1024, "without LEOM and without allow-split", new_vtapes => 1);
1194 make_holding_file(1024*1024, "localhost", "/usr");
1195 like(taper_reply, qr/^TAPER-OK worker0$/,
1196         "got TAPER-OK") or die;
1197 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 262144 \"\" \"\" \"0\" \"\" \"\" \"\" \"\" 1612");
1198 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1199         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1200 taper_cmd("START-SCAN worker0 $handle");
1201 taper_cmd("NEW-TAPE worker0 $handle");
1202 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1203         "got proper NEW-TAPE worker0 $handle") or die;
1204 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ bytes \d* kps [\d.]+ orig-kb 1612\]" "" "No space left on device, splitting not enabled"$/,
1205         "got PARTIAL for filenum 1") or die;
1206 taper_cmd("QUIT");
1207 wait_for_exit();
1208
1209 check_logs([
1210     qr(^INFO taper Slot 1 without label can be labeled$),
1211     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1212     qr(^PARTPARTIAL taper TESTCONF01 1 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ bytes 983040 kps [\d.]+ orig-kb 1612\] \"No space left on device\"$),
1213     qr(^PARTIAL taper localhost /usr $datestamp 1 0 \[sec [\d.]+ bytes 0 kps [\d.]+ orig-kb 1612\] "No space left on device, splitting not enabled"$),
1214     qr(^INFO taper tape TESTCONF01 kb 0 fm 1 \[OK\]$),
1215 ], "without LEOM and without allow-split logged correctly");
1216 cleanup_log();
1217
1218 ##
1219 # A run with LEOM and without allow-split
1220 $handle = "77-11112";
1221 $datestamp = "20090303020000";
1222 run_taper(1024, "with LEOM and without allow-split", new_vtapes => 1, leom => 1);
1223 make_holding_file(1024*1024, "localhost", "/usr");
1224 like(taper_reply, qr/^TAPER-OK worker0$/,
1225         "got TAPER-OK") or die;
1226 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 262144 \"\" \"\" \"0\" \"\" \"\" \"\" \"\" 1612");
1227 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1228         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1229 taper_cmd("START-SCAN worker0 $handle");
1230 taper_cmd("NEW-TAPE worker0 $handle");
1231 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1232         "got proper NEW-TAPE worker0 $handle") or die;
1233 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 864 "\[sec [\d.]+ bytes 884736 kps [\d.]+ orig-kb 1612\]"$/,
1234         "got PARTDONE for filenum 1") or die;
1235 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ bytes 884736 kps [\d.]+ orig-kb 1612\]" "" "No space left on device, splitting not enabled"$/,
1236         "got PARTIAL") or die;
1237 taper_cmd("QUIT");
1238 wait_for_exit();
1239
1240 check_logs([
1241     qr(^INFO taper Slot 1 without label can be labeled$),
1242     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1243     qr(^PART taper TESTCONF01 1 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ bytes 884736 kps [\d.]+ orig-kb 1612\]$),
1244     qr(^PARTIAL taper localhost /usr $datestamp 1 0 \[sec [\d.]+ bytes 884736 kps [\d.]+ orig-kb 1612\] "No space left on device, splitting not enabled"$),
1245     qr(^INFO taper tape TESTCONF01 kb 864 fm 1 \[OK\]$),
1246 ], "with LEOM and without allow-split logged correctly");
1247 cleanup_log();
1248
1249 ## test lexical with new changer
1250
1251 ##
1252 # A simple, one-part FILE-WRITE
1253 $handle = "11-11111";
1254 $datestamp = "20070102030405";
1255 run_taper(4096, "single-part and multipart FILE-WRITE", taperscan => "lexical", new_vtapes => 1);
1256 like(taper_reply, qr/^TAPER-OK worker0$/,
1257         "got TAPER-OK") or die;
1258 make_holding_file(1024*1024, "localhost", "/home");
1259 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp \"\" \"\" \"\" \"\" \"\" \"\" \"\" \"\" 12");
1260 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1261         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1262 taper_cmd("START-SCAN worker0 $handle");
1263 taper_cmd("NEW-TAPE worker0 $handle");
1264 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1265         "got proper NEW-TAPE worker0 $handle") or die;
1266 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 1024 "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]"$/,
1267         "got PARTDONE") or die;
1268 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]" "" ""$/,
1269         "got DONE") or die;
1270
1271 ##
1272 # A multipart FILE-WRITE, using the same taper instance
1273 #  (note that the third part is of length 0, and is not logged)
1274
1275 $handle = '11-22222';
1276 make_holding_file(1024*1024, "localhost", "/usr");
1277 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 524288 \"\" \"\" 1 \"\" \"\" \"\" \"\" 512");
1278 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 512 "\[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]"$/,
1279         "got PARTDONE for filenum 2") or die;
1280 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 512 "\[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]"$/,
1281         "got PARTDONE for filenum 3") or die;
1282 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 512\]" "" ""$/,
1283         "got DONE") or die;
1284 taper_cmd("QUIT");
1285 wait_for_exit();
1286
1287 check_logs([
1288     qr(^INFO taper Slot 1 without label can be labeled$),
1289     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1290     qr(^PART taper TESTCONF01 1 localhost /home $datestamp 1/-1 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]$),
1291     qr(^DONE taper localhost /home $datestamp 1 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 12\]$),
1292     qr(^PART taper TESTCONF01 2 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]$),
1293     qr(^PART taper TESTCONF01 3 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ bytes 524288 kps [\d.]+ orig-kb 512\]$),
1294     qr(^DONE taper localhost /usr $datestamp 2 0 \[sec [\d.]+ bytes 1048576 kps [\d.]+ orig-kb 512\]$),
1295     qr(^INFO taper tape TESTCONF01 kb 2048 fm 4 \[OK\]$),
1296 ], "single-part and multi-part dump logged correctly");
1297
1298 ##
1299 # Test a sequence of writes to the same set of tapes
1300
1301 $handle = "33-11111";
1302 $datestamp = "20090101010000";
1303 run_taper(1024, "first in a sequence", taperscan => "lexical", new_vtapes => 1);
1304 like(taper_reply, qr/^TAPER-OK worker0$/,
1305         "got TAPER-OK") or die;
1306 make_holding_file(500000, "localhost", "/u01");
1307 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1412");
1308 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1309         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1310 taper_cmd("START-SCAN worker0 $handle");
1311 taper_cmd("NEW-TAPE worker0 $handle");
1312 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1313         "got proper NEW-TAPE worker0 $handle") or die;
1314 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1412\]"$/,
1315         "got PARTDONE for filenum 1") or die;
1316 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 232 "\[sec [\d.]+ bytes 237856 kps [\d.]+ orig-kb 1412\]"$/,
1317         "got PARTDONE for filenum 2") or die;
1318 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 500000 kps [\d.]+ orig-kb 1412\]" "" ""$/,
1319         "got DONE") or die;
1320 $handle = "33-22222";
1321 make_holding_file(614400, "localhost", "/u02");
1322 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1512");
1323 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]"$/,
1324         "got PARTDONE for filenum 3") or die;
1325 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1326         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1327 taper_cmd("START-SCAN worker0 $handle");
1328 taper_cmd("NEW-TAPE worker0 $handle");
1329 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1330         "got proper NEW-TAPE worker0 $handle") or die;
1331 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]"$/,
1332         "got PARTDONE for filenum 1 on second tape") or die;
1333 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1512\]"$/,
1334         "got PARTDONE for filenum 2 on second tape") or die;
1335 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1512\]" "" ""$/,
1336         "got DONE") or die;
1337 taper_cmd("QUIT");
1338 wait_for_exit();
1339
1340 check_logs([
1341     qr(^INFO taper Slot 1 without label can be labeled$),
1342     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1343     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1412\]$),
1344     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 237856 kps [\d.]+ orig-kb 1412\]$),
1345     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 500000 kps [\d.]+ orig-kb 1412\]$),
1346     qr(^PART taper TESTCONF01 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]$),
1347     qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 98304 kps [\d.]+ orig-kb 1512\] "No space left on device"$),
1348     qr(^INFO taper Will request retry of failed split part\.$),
1349     qr(^INFO taper tape TESTCONF01 kb 744 fm 4 \[OK\]$),
1350     qr(^INFO taper Slot 2 without label can be labeled$),
1351     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1352     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1512\]$),
1353     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1512\]$),
1354     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1512\]$),
1355     qr(^INFO taper tape TESTCONF02 kb 344 fm 2 \[OK\]$),
1356 ], "first taper invocation in sequence logged correctly");
1357 cleanup_log();
1358
1359 $handle = "33-33333";
1360 $datestamp = "20090202020000";
1361 run_taper(1024, "second in a sequence", keep_config => 1);
1362 like(taper_reply, qr/^TAPER-OK worker0$/,
1363         "got TAPER-OK") or die;
1364 make_holding_file(300000, "localhost", "/u01");
1365 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
1366 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1367         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1368 taper_cmd("START-SCAN worker0 $handle");
1369 taper_cmd("NEW-TAPE worker0 $handle");
1370 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF03$/,
1371         "got proper NEW-TAPE worker0 $handle") or die;
1372 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
1373         "got PARTDONE for filenum 1") or die;
1374 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 2 36 "\[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]"$/,
1375         "got PARTDONE for filenum 2") or die;
1376 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]" "" ""$/,
1377         "got DONE") or die;
1378 $handle = "33-44444";
1379 make_holding_file(614400, "localhost", "/u02");
1380 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
1381 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 3 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
1382         "got PARTDONE for filenum 3") or die;
1383 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 4 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
1384         "got PARTDONE for filenum 4") or die;
1385 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1386         "got REQUEST-NEW-TAPE worker0 $handle") or die;
1387 taper_cmd("START-SCAN worker0 $handle");
1388 taper_cmd("NEW-TAPE worker0 $handle");
1389 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1390         "got proper NEW-TAPE worker0 $handle") or die;
1391 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]"$/,
1392         "got PARTDONE for filenum 1 on second tape") or die;
1393 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]" "" ""$/,
1394         "got DONE") or die;
1395 taper_cmd("QUIT");
1396 wait_for_exit();
1397
1398 check_logs([
1399     qr(^INFO taper Slot 3 without label can be labeled$),
1400     qr(^START taper datestamp $datestamp label TESTCONF03 tape 1$),
1401     qr(^PART taper TESTCONF03 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
1402     qr(^PART taper TESTCONF03 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]$),
1403     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]$),
1404     qr(^PART taper TESTCONF03 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
1405     qr(^PART taper TESTCONF03 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
1406     qr(^PARTPARTIAL taper TESTCONF03 5 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 0 kps [\d.]+ orig-kb 1712\] "No space left on device"$),
1407     qr(^INFO taper Will request retry of failed split part\.$),
1408     qr(^INFO taper tape TESTCONF03 kb 804 fm 5 \[OK\]$),
1409     qr(^INFO taper Slot 1 with label TESTCONF01 is usable$),
1410     qr(^START taper datestamp $datestamp label TESTCONF01 tape 2$),
1411     qr(^PART taper TESTCONF01 1 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]$),
1412     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]$),
1413     qr(^INFO taper tape TESTCONF01 kb 88 fm 1 \[OK\]$),
1414 ], "second taper invocation in sequence logged correctly");
1415 cleanup_log();
1416
1417 ##
1418 # A run with a bogus tapedev/tpchanger
1419 $handle = "44-11111";
1420 $datestamp = "20070102030405";
1421 run_taper(4096, "no tapedev", notapedev => 1, taperscan => "lexical", new_vtapes => 1);
1422 like(taper_reply, qr/^TAPE-ERROR SETUP "You must specify one of 'tapedev' or 'tpchanger'"$/,
1423         "got TAPE-ERROR") or die;
1424 wait_for_exit();
1425
1426 ##
1427 # A run with 2 workers
1428 $handle0 = "66-00000";
1429 $handle1 = "66-11111";
1430 $datestamp = "20090202020000";
1431 run_taper(1024, "with 2 workers", new_vtapes => 1, taperscan => "lexical", new_vtapes => 1);
1432 like(taper_reply, qr/^TAPER-OK worker0$/,
1433         "got TAPER-OK") or die;
1434 taper_cmd("START-TAPER worker1 $datestamp");
1435 like(taper_reply, qr/^TAPER-OK worker1$/,
1436        "got TAPER-OK") or die;
1437 make_holding_file(300000, "localhost", "/u01");
1438 taper_cmd("FILE-WRITE worker0 $handle0 \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
1439 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle0$/,
1440         "got REQUEST-NEW-TAPE worker0 $handle0") or die;
1441 taper_cmd("START-SCAN worker0 $handle0");
1442 taper_cmd("NEW-TAPE worker0 $handle0");
1443 like(taper_reply, qr/^NEW-TAPE $handle0 TESTCONF01$/,
1444         "got proper NEW-TAPE worker0 $handle0") or die;
1445 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]"$/,
1446         "got PARTDONE for filenum 1") or die;
1447 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 2 36 "\[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]"$/,
1448         "got PARTDONE for filenum 2") or die;
1449 like(taper_reply, qr/^DONE $handle0 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]" "" ""$/,
1450         "got DONE") or die;
1451 make_holding_file(614400, "localhost", "/u02");
1452 taper_cmd("FILE-WRITE worker1 $handle1 \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
1453 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle1$/,
1454         "got REQUEST-NEW-TAPE worker1 $handle1") or die;
1455 taper_cmd("START-SCAN worker1 $handle1");
1456 taper_cmd("NEW-TAPE worker1 $handle1");
1457 like(taper_reply, qr/^NEW-TAPE $handle1 TESTCONF02$/,
1458         "got proper NEW-TAPE worker1 $handle1") or die;
1459 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 1 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
1460         "got PARTDONE for filenum 1 on second tape") or die;
1461 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 2 256 "\[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]"$/,
1462         "got PARTDONE for filenum 2 on second tape") or die;
1463 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 3 88 "\[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]"$/,
1464         "got PARTDONE for filenum 3 on second tape") or die;
1465 like(taper_reply, qr/^DONE $handle1 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]" "" ""$/,
1466         "got DONE") or die;
1467 taper_cmd("QUIT");
1468 wait_for_exit();
1469
1470 check_logs([
1471     qr(^INFO taper Slot 1 without label can be labeled$),
1472     qr(^INFO taper Slot 1 is already in use by drive.*$),
1473     qr(^INFO taper Slot 2 without label can be labeled$),
1474     qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1475     qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1612\]$),
1476     qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ bytes 37856 kps [\d.]+ orig-kb 1612\]$),
1477     qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ bytes 300000 kps [\d.]+ orig-kb 1612\]$),
1478     qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1479     qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
1480     qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ bytes 262144 kps [\d.]+ orig-kb 1712\]$),
1481     qr(^PART taper TESTCONF02 3 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ bytes 90112 kps [\d.]+ orig-kb 1712\]$),
1482     qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ bytes 614400 kps [\d.]+ orig-kb 1712\]$),
1483     qr(^INFO taper tape TESTCONF01 kb 292 fm 2 \[OK\]$),
1484     qr(^INFO taper tape TESTCONF02 kb 600 fm 3 \[OK\]$),
1485 ], "two workers logged correctly");
1486 cleanup_log();
1487
1488 cleanup_taper();