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

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