1 # Copyright (c) 2009, 2010 Zmanda, Inc. All Rights Reserved.
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.
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
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
16 # Contact information: Zmanda Inc, 465 S. Mathilda Ave., Suite 300
17 # Sunnyvale, CA 94086, USA, or: http://www.zmanda.com
19 use Test::More tests => 201;
23 use lib '@amperldir@';
24 use Installcheck::Run;
25 use Installcheck::Mock;
30 use POSIX ":sys_wait_h";
34 use Amanda::Header qw( :constants );
37 use Amanda::Device qw( :constants );
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
47 # This uses IPC::Open3 instead of Expect mainly because the interactions
48 # are so carefully scripted that Expect is not required.
50 # put the debug messages somewhere
51 Amanda::Debug::dbopen("installcheck");
52 Installcheck::log_test_output();
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'};
58 # information on the current run
59 my ($datestamp, $handle);
60 my ($taper_pid, $taper_in, $taper_out, $last_taper_reply, $taper_reply_timeout);
63 my ($length, $description, %params) = @_;
67 unless ($params{'keep_config'}) {
69 if ($params{'new_vtapes'}) {
70 $testconf = Installcheck::Run::setup(1);
72 $testconf = Installcheck::Run::setup();
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'};
81 $ndmp->config($testconf);
83 unless ($params{'leom'} or $params{'ndmp_server'}) {
84 $testconf->add_param('device_property', '"LEOM" "OFF"');
86 $testconf->add_param('debug_taper', '9'); ## TEMPORARY
87 $testconf->add_tapetype('TEST-TAPE', [
88 'length' => "$length",
93 open(TAPER_ERR, ">", $taper_stderr_file);
94 $taper_in = $taper_out = '';
95 $taper_pid = open3($taper_in, $taper_out, ">&TAPER_ERR",
96 "$amlibexecdir/taper", "TESTCONF");
98 $taper_in->blocking(1);
99 $taper_out->autoflush();
101 if ($params{'keep_config'}) {
102 pass("spawned new taper for $description (same config)");
104 pass("spawned taper for $description (tape length $length kb)");
107 # define this to get the installcheck to wait and allow you to attach
108 # a gdb instance to the taper
109 if ($params{'use_gdb'}) {
110 $taper_reply_timeout = 0; # no timeouts while debugging
111 diag("attach debugger to pid $taper_pid and press ENTER");
114 $taper_reply_timeout = 120;
117 taper_cmd("START-TAPER worker0 $datestamp");
122 waitpid($taper_pid, 0);
128 -f $test_filename and unlink($test_filename);
129 -f $taper_stderr_file and unlink($taper_stderr_file);
131 # make a small effort to collect zombies
133 if (waitpid($taper_pid, WNOHANG) == $taper_pid) {
142 diag(">>> $cmd") if $debug;
143 print $taper_in "$cmd\n";
147 local $SIG{ALRM} = sub { die "Timeout while waiting for reply\n" };
148 alarm($taper_reply_timeout);
149 $last_taper_reply = $taper_out->getline();
152 if (!$last_taper_reply) {
153 die("wrong pid") unless ($taper_pid == waitpid($taper_pid, 0));
154 my $exit_status = $?;
156 open(my $fh, "<", $taper_stderr_file) or die("open $taper_stderr_file: $!");
157 my $stderr = do { local $/; <$fh> };
160 diag("taper stderr:\n$stderr") if $stderr;
161 die("taper (pid $taper_pid) died unexpectedly with status $exit_status");
164 # trim trailing whitespace -- C taper outputs an extra ' ' after
165 # single-word replies
166 $last_taper_reply =~ s/\s*$//;
167 diag("<<< $last_taper_reply") if $debug;
169 return $last_taper_reply;
173 my ($expected, $msg) = @_;
177 # must contain a pid line at the beginning and end
178 unshift @$expected, qr/^INFO taper taper pid \d+$/;
179 push @$expected, qr/^INFO taper pid-done \d+$/;
181 open(my $logfile, "<", "$CONFIG_DIR/TESTCONF/log/log")
182 or die("opening log: $!");
183 my @logfile = grep(/^\S+ taper /, <$logfile>);
186 while (@logfile and @$expected) {
187 my $logline = shift @logfile;
188 my $expline = shift @$expected;
190 if ($logline !~ $expline) {
191 like($logline, $expline, $msg);
196 fail("$msg (extra trailing log lines)");
200 fail("$msg (logfile ends early)");
201 diag("first missing line should match ");
202 diag("".$expected->[0]);
210 my $logfile = "$CONFIG_DIR/TESTCONF/log/log";
211 -f $logfile and unlink($logfile);
214 # functions to create dumpfiles
216 sub write_dumpfile_header_to {
217 my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
219 my $hdr = Amanda::Header->new();
220 $hdr->{'type'} = $Amanda::Header::F_DUMPFILE;
221 $hdr->{'datestamp'} = $datestamp;
222 $hdr->{'dumplevel'} = 0;
223 $hdr->{'compressed'} = 0;
224 $hdr->{'comp_suffix'} = ".foo";
225 $hdr->{'name'} = $hostname;
226 $hdr->{'disk'} = $disk;
227 $hdr->{'program'} = "INSTALLCHECK";
228 $hdr = $hdr->to_string(32768,32768);
230 $fh->syswrite($hdr, 32768);
233 sub write_dumpfile_data_to {
234 my ($fh, $size, $hostname, $disk, $expect_failure) = @_;
236 my $bytes_to_write = $size;
237 my $bufbase = substr((('='x127)."\n".('-'x127)."\n") x 4, 8, -3) . "1K\n";
238 die length($bufbase) unless length($bufbase) == 1024-8;
240 while ($bytes_to_write > 0) {
241 my $buf = sprintf("%08x", $k++).$bufbase;
242 my $written = $fh->syswrite($buf, $bytes_to_write);
243 if (!defined($written)) {
244 die "writing: $!" unless $expect_failure;
247 $bytes_to_write -= $written;
251 # make a new holding-like file in test_filename
252 sub make_holding_file {
253 my ($size, $hostname, $disk) = @_;
254 open(my $fh, ">", $test_filename);
255 write_dumpfile_header_to($fh, $size, $hostname, $disk);
256 write_dumpfile_data_to($fh, $size, $hostname, $disk);
259 # connect to the given port and write a dumpfile; this *will* create
260 # zombies, but it's OK -- installchecks aren't daemons.
262 my ($port_cmd, $size, $hostname, $disk, $expect_error) = @_;
264 my ($header_port, $data_addr) =
265 ($last_taper_reply =~ /^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+)/);
267 # just run this in the child
268 return unless fork() == 0;
270 my $sock = IO::Socket::INET->new(
271 PeerAddr => "127.0.0.1:$header_port",
276 write_dumpfile_header_to($sock, $size, $hostname, $disk, $expect_error);
279 $sock = IO::Socket::INET->new(
280 PeerAddr => $data_addr,
285 write_dumpfile_data_to($sock, $size, $hostname, $disk, $expect_error);
292 # A simple, one-part FILE-WRITE
293 $handle = "11-11111";
294 $datestamp = "20070102030405";
295 run_taper(4096, "single-part and multipart FILE-WRITE");
296 like(taper_reply, qr/^TAPER-OK worker0$/,
297 "got TAPER-OK") or die;
298 make_holding_file(1024*1024, "localhost", "/home");
299 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp \"\" \"\" \"\" \"\" \"\" \"\" \"\" \"\" 12");
300 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
301 "got REQUEST-NEW-TAPE worker0 $handle") or die;
302 taper_cmd("START-SCAN worker0 $handle");
303 taper_cmd("NEW-TAPE worker0 $handle");
304 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
305 "got proper NEW-TAPE worker0 $handle") or die;
306 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 1024 "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]"$/,
307 "got PARTDONE") or die;
308 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]" "" ""$/,
312 # A multipart FILE-WRITE, using the same taper instance
313 # (note that the third part is of length 0, and is not logged)
315 $handle = '11-22222';
316 make_holding_file(1024*1024, "localhost", "/usr");
317 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp 524288 \"\" \"\" 1 \"\" \"\" \"\" \"\" 512");
318 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 512 "\[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]"$/,
319 "got PARTDONE for filenum 2") or die;
320 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 512 "\[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]"$/,
321 "got PARTDONE for filenum 3") or die;
322 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 512\]" "" ""$/,
328 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
329 qr(^PART taper TESTCONF01 1 localhost /home $datestamp 1/-1 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]$),
330 qr(^DONE taper localhost /home $datestamp 1 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 12\]$),
331 qr(^PART taper TESTCONF01 2 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]$),
332 qr(^PART taper TESTCONF01 3 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 512 kps [\d.]+ orig-kb 512\]$),
333 qr(^DONE taper localhost /usr $datestamp 2 0 \[sec [\d.]+ kb 1024 kps [\d.]+ orig-kb 512\]$),
334 qr(^INFO taper tape TESTCONF01 kb 2048 fm 4 \[OK\]$),
335 ], "single-part and multi-part dump logged correctly");
337 # check out the headers on those files, just to be sure
339 my $dev = Amanda::Device->new("file:" . Installcheck::Run::vtape_dir());
340 die("bad device: " . $dev->error_or_status()) unless $dev->status == $DEVICE_STATUS_SUCCESS;
342 $dev->start($ACCESS_READ, undef, undef)
343 or die("can't start device: " . $dev->error_or_status());
346 my ($hdr, $expected, $msg) = @_;
348 for (keys %$expected) { $got->{$_} = "".$hdr->{$_}; }
349 if (!is_deeply($got, $expected, $msg)) {
350 diag("got: " . Dumper($got));
354 is_hdr($dev->seek_file(1), {
355 type => $F_SPLIT_DUMPFILE,
356 datestamp => $datestamp,
359 }, "header on file 1 is correct");
361 is_hdr($dev->seek_file(2), {
362 type => $F_SPLIT_DUMPFILE,
363 datestamp => $datestamp,
368 }, "header on file 2 is correct");
370 is_hdr($dev->seek_file(3), {
371 type => $F_SPLIT_DUMPFILE,
372 datestamp => $datestamp,
377 }, "header on file 3 is correct");
379 is_hdr($dev->seek_file(4), {
380 type => $F_SPLIT_DUMPFILE,
381 datestamp => $datestamp,
386 }, "header on file 4 is correct");
390 # A PORT-WRITE with no disk buffer
392 $handle = "11-33333";
393 $datestamp = "19780615010203";
394 run_taper(4096, "multipart PORT-WRITE");
395 like(taper_reply, qr/^TAPER-OK worker0$/,
396 "got TAPER-OK") or die;
397 taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 524288 \"\" 393216 1 0 \"\" \"\" 0 AMANDA");
398 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
399 "got PORT with data address");
400 write_to_port($last_taper_reply, 63*32768, "localhost", "/var", 0);
401 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
402 "got REQUEST-NEW-TAPE worker0 $handle") or die;
403 taper_cmd("START-SCAN worker0 $handle");
404 taper_cmd("NEW-TAPE worker0 $handle");
405 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
406 "got proper NEW-TAPE worker0 $handle") or die;
407 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
408 "got PARTDONE for filenum 1") or die;
409 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
410 "got PARTDONE for filenum 2") or die;
411 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
412 "got PARTDONE for filenum 3") or die;
413 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
414 "got PARTDONE for filenum 4") or die;
415 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 5 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
416 "got PARTDONE for filenum 5") or die;
417 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 6 96 "\[sec [\d.]+ kb 96 kps [\d.]+\]"$/,
418 "got PARTDONE for filenum 6") or die;
419 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
420 "got DUMPER-STATUS request") or die;
421 taper_cmd("DONE worker0 $handle 712");
422 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 2016 kps [\d.]+ orig-kb 712\]" "" ""$/,
428 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
429 qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
430 qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
431 qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
432 qr(^PART taper TESTCONF01 4 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
433 qr(^PART taper TESTCONF01 5 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
434 qr(^PART taper TESTCONF01 6 localhost /var $datestamp 6/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+\]$),
435 qr(^DONE taper localhost /var $datestamp 6 0 \[sec [\d.]+ kb 2016 kps [\d.]+ orig-kb 712\]$),
436 qr(^INFO taper tape TESTCONF01 kb 2016 fm 6 \[OK\]$),
437 ], "multipart PORT-WRITE logged correctly");
442 $handle = "11-44444";
443 $datestamp = "19411207000000";
444 run_taper(4096, "testing NO-NEW-TAPE from the driver on 1st request");
445 like(taper_reply, qr/^TAPER-OK worker0$/,
446 "got TAPER-OK") or die;
447 make_holding_file(1024*1024, "localhost", "/home");
448 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /home 0 $datestamp 0 \"\" 0 1 0 \"\" \"\" 0 912");
449 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
450 "got REQUEST-NEW-TAPE worker0 $handle") or die;
451 taper_cmd("NO-NEW-TAPE worker0 $handle sorry");
452 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
453 "got FAILED") or die;
458 qr(^ERROR taper no-tape config \[sorry\]$),
459 qr(^FAIL taper localhost /home $datestamp 0 config sorry$),
460 ], "NO-NEW-TAPE logged correctly");
463 # Test retrying on EOT (via PORT-WRITE with a mem cache)
465 $handle = "11-55555";
466 $datestamp = "19750711095836";
467 run_taper(1024, "PORT-WRITE retry on EOT (mem cache)");
468 like(taper_reply, qr/^TAPER-OK worker0$/,
469 "got TAPER-OK") or die;
470 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"\" 786432 1 0 \"\" \"\" 0 AMANDA");
471 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
472 "got PORT with data address");
473 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
474 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
475 "got REQUEST-NEW-TAPE worker0 $handle") or die;
476 taper_cmd("START-SCAN worker0 $handle");
477 taper_cmd("NEW-TAPE worker0 $handle");
478 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
479 "got proper NEW-TAPE worker0 $handle") or die;
480 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
481 "got PARTDONE for filenum 1") or die;
482 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
483 "got REQUEST-NEW-TAPE worker0 $handle") or die;
484 taper_cmd("START-SCAN worker0 $handle");
485 taper_cmd("NEW-TAPE worker0 $handle");
486 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
487 "got proper NEW-TAPE worker0 $handle") or die;
488 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
489 "got PARTDONE for filenum 1 on second tape") or die;
490 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+\]"$/,
491 "got PARTDONE for filenum 2 on second tape") or die;
492 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
493 "got DUMPER-STATUS request") or die;
494 taper_cmd("DONE worker0 $handle 1012");
495 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1012\]" "" ""$/,
501 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
502 qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
503 qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+\] "No space left on device"$),
504 qr(^INFO taper Will request retry of failed split part\.$),
505 qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
506 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
507 qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
508 qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+\]$),
509 qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1012\]$),
510 qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
511 ], "multivolume PORT-WRITE logged correctly");
514 # Test retrying on EOT (via FILE-WRITE)
516 $handle = "11-66666";
517 $datestamp = "19470815000000";
518 run_taper(1024, "FILE-WRITE retry on EOT");
519 like(taper_reply, qr/^TAPER-OK worker0$/,
520 "got TAPER-OK") or die;
521 make_holding_file(1575936, "localhost", "/usr");
522 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /usr 0 $datestamp \"\" \"\" \"\" 1 786432 \"\" \"\" \"\" 1112");
523 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
524 "got REQUEST-NEW-TAPE worker0 $handle") or die;
525 taper_cmd("START-SCAN worker0 $handle");
526 taper_cmd("NEW-TAPE worker0 $handle");
527 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
528 "got proper NEW-TAPE worker0 $handle") or die;
529 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]"$/,
530 "got PARTDONE for filenum 1") or die;
531 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
532 "got REQUEST-NEW-TAPE worker0 $handle") or die;
533 taper_cmd("START-SCAN worker0 $handle");
534 taper_cmd("NEW-TAPE worker0 $handle");
535 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
536 "got proper NEW-TAPE worker0 $handle") or die;
537 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]"$/,
538 "got PARTDONE for filenum 1 on second tape") or die;
539 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+ orig-kb 1112\]"$/,
540 "got PARTDONE for filenum 2 on second tape") or die;
541 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1112\]" "" ""$/,
547 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
548 qr(^PART taper TESTCONF01 1 localhost /usr $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]$),
549 qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+ orig-kb 1112\] "No space left on device"$),
550 qr(^INFO taper Will request retry of failed split part\.$),
551 qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
552 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
553 qr(^PART taper TESTCONF02 1 localhost /usr $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+ orig-kb 1112\]$),
554 qr(^PART taper TESTCONF02 2 localhost /usr $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+ orig-kb 1112\]$),
555 qr(^DONE taper localhost /usr $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1112\]$),
556 qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
557 ], "multivolume FILE-WRITE logged correctly");
560 # Test retrying on EOT (via PORT-WRITE with a disk cache)
562 $handle = "11-77777";
563 $datestamp = "20090427212500";
564 run_taper(1024, "PORT-WRITE retry on EOT (disk cache)");
565 like(taper_reply, qr/^TAPER-OK worker0$/,
566 "got TAPER-OK") or die;
567 taper_cmd("PORT-WRITE worker0 $handle localhost /usr/local 0 $datestamp 786432 \"$Installcheck::TMP\" 786432 1 0 \"\" \"\" 0 AMANDA");
568 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
569 "got PORT with data address");
570 write_to_port($last_taper_reply, 1575936, "localhost", "/usr/local", 0);
571 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
572 "got REQUEST-NEW-TAPE worker0 $handle") or die;
573 taper_cmd("START-SCAN worker0 $handle");
574 taper_cmd("NEW-TAPE worker0 $handle");
575 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
576 "got proper NEW-TAPE worker0 $handle") or die;
577 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
578 "got PARTDONE for filenum 1") or die;
579 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
580 "got REQUEST-NEW-TAPE worker0 $handle") or die;
581 taper_cmd("START-SCAN worker0 $handle");
582 taper_cmd("NEW-TAPE worker0 $handle");
583 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
584 "got proper NEW-TAPE worker0 $handle") or die;
585 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 768 "\[sec [\d.]+ kb 768 kps [\d.]+\]"$/,
586 "got PARTDONE for filenum 1 on second tape") or die;
587 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 3 "\[sec [\d.]+ kb 3 kps [\d.]+\]"$/,
588 "got PARTDONE for filenum 2 on second tape") or die;
589 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
590 "got DUMPER-STATUS request") or die;
591 taper_cmd("DONE worker0 $handle 1212");
592 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1212\]" "" ""$/,
598 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
599 qr(^PART taper TESTCONF01 1 localhost /usr/local $datestamp 1/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
600 qr(^PARTPARTIAL taper TESTCONF01 2 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+\] "No space left on device"$),
601 qr(^INFO taper Will request retry of failed split part\.$),
602 qr(^INFO taper tape TESTCONF01 kb 768 fm 2 \[OK\]$),
603 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
604 qr(^PART taper TESTCONF02 1 localhost /usr/local $datestamp 2/-1 0 \[sec [\d.]+ kb 768 kps [\d.]+\]$),
605 qr(^PART taper TESTCONF02 2 localhost /usr/local $datestamp 3/-1 0 \[sec [\d.]+ kb 3 kps [\d.]+\]$),
606 qr(^DONE taper localhost /usr/local $datestamp 3 0 \[sec [\d.]+ kb 1539 kps [\d.]+ orig-kb 1212\]$),
607 qr(^INFO taper tape TESTCONF02 kb 771 fm 2 \[OK\]$),
608 ], "multivolume PORT-WRITE (disk cache) logged correctly");
611 # Test failure on EOT (via PORT-WRITE with no cache), and a new try on the
614 $handle = "11-88888";
615 $datestamp = "20090424173000";
616 run_taper(1024, "PORT-WRITE failure on EOT (no cache)");
617 like(taper_reply, qr/^TAPER-OK worker0$/,
618 "got TAPER-OK") or die;
619 taper_cmd("PORT-WRITE worker0 $handle localhost /var/log 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
620 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
621 "got PORT with data address");
622 write_to_port($last_taper_reply, 1575936, "localhost", "/var/log", 1);
623 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
624 "got REQUEST-NEW-TAPE worker0 $handle") or die;
625 taper_cmd("START-SCAN worker0 $handle");
626 taper_cmd("NEW-TAPE worker0 $handle");
627 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
628 "got proper NEW-TAPE worker0 $handle") or die;
629 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ kb 0 kps [\d.]+\]" "" "No space left on device"$/,
630 "got PARTIAL") or die;
631 # retry on the next tape
632 $handle = "11-88899";
633 taper_cmd("PORT-WRITE worker0 $handle localhost /boot 0 $datestamp 0 \"\" 0 0 0 \"\" \"\" 0 AMANDA");
634 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
635 "got PORT with data address");
636 write_to_port($last_taper_reply, 65536, "localhost", "/boot", 0);
637 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
638 "got REQUEST-NEW-TAPE worker0 $handle") or die;
639 taper_cmd("START-SCAN worker0 $handle");
640 taper_cmd("NEW-TAPE worker0 $handle");
641 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
642 "got proper NEW-TAPE worker0 $handle") or die;
643 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 64 "\[sec [\d.]+ kb 64 kps [\d.]+\]"$/,
644 "got PARTDONE for filenum 1 on second tape") or die;
645 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
646 "got DUMPER-STATUS request") or die;
647 taper_cmd("DONE worker0 $handle 64");
648 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 64 kps [\d.]+ orig-kb 64\]" "" ""$/,
654 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
655 qr(^PARTPARTIAL taper TESTCONF01 1 localhost /var/log $datestamp 1/-1 0 \[sec [\d.]+ kb 960 kps [\d.]+\] "No space left on device"$),
656 qr(^PARTIAL taper localhost /var/log $datestamp 1 0 \[sec [\d.]+ kb 0 kps [\d.]+\] "No space left on device"$),
657 qr(^INFO taper tape TESTCONF01 kb 0 fm 1 \[OK\]$),
658 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
659 qr(^PART taper TESTCONF02 1 localhost /boot $datestamp 1/-1 0 \[sec [\d.]+ kb 64 kps [\d.]+\]$),
660 qr(^DONE taper localhost /boot $datestamp 1 0 \[sec [\d.]+ kb 64 kps [\d.]+ orig-kb 64\]$),
661 qr(^INFO taper tape TESTCONF02 kb 64 fm 1 \[OK\]$),
662 ], "failure on EOT (no cache) with subsequent dump logged correctly");
665 # Test running out of tapes (second REQUEST-NEW-TAPE fails)
667 $handle = "11-99999";
668 $datestamp = "20100101000000";
669 run_taper(512, "FILE-WRITE runs out of tapes");
670 like(taper_reply, qr/^TAPER-OK worker0$/,
671 "got TAPER-OK") or die;
672 make_holding_file(512*1024, "localhost", "/music");
673 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /music 0 $datestamp \"\" \"\" \"\" 1 262144 \"none\" \"\" 10240 1312");
674 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
675 "got REQUEST-NEW-TAPE worker0 $handle") or die;
676 taper_cmd("START-SCAN worker0 $handle");
677 taper_cmd("NEW-TAPE worker0 $handle");
678 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
679 "got proper NEW-TAPE worker0 $handle") or die;
680 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]"$/,
681 "got PARTDONE for filenum 1 on first tape") or die;
682 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
683 "got REQUEST-NEW-TAPE worker0 $handle") or die;
684 taper_cmd("NO-NEW-TAPE worker0 $handle \"that's enough\"");
685 like(taper_reply, qr/^PARTIAL $handle INPUT-GOOD TAPE-ERROR "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]" "" "that's enough"$/,
686 "got PARTIAL") or die;
691 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
692 qr(^PART taper TESTCONF01 1 localhost /music $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\]$),
693 qr(^PARTPARTIAL taper TESTCONF01 2 localhost /music $datestamp 2/-1 0 \[sec [\d.]+ kb 160 kps [\d.]+ orig-kb 1312\] "No space left on device"$),
694 qr(^INFO taper Will request retry of failed split part\.$),
695 qr(^INFO taper tape TESTCONF01 kb 256 fm 2 \[OK\]$),
696 qr(^ERROR taper no-tape config \[that's enough\]$),
697 qr(^PARTIAL taper localhost /music $datestamp 2 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1312\] "that's enough"$),
698 ], "running out of tapes (simulating runtapes=1) logged correctly");
701 # A PORT-WRITE with no disk buffer
703 $handle = "22-00000";
704 $datestamp = "20200202222222";
705 run_taper(4096, "multipart PORT-WRITE");
706 like(taper_reply, qr/^TAPER-OK worker0$/,
707 "got TAPER-OK") or die;
708 taper_cmd("PORT-WRITE worker0 $handle localhost /sbin 0 $datestamp 999999 \"\" 655360 1 \"\" \"\" \"\" \"\" AMANDA");
709 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
710 "got PORT with data address");
711 write_to_port($last_taper_reply, 63*32768, "localhost", "/sbin", 0);
712 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
713 "got REQUEST-NEW-TAPE worker0 $handle") or die;
714 taper_cmd("START-SCAN worker0 $handle");
715 taper_cmd("NEW-TAPE worker0 $handle");
716 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
717 "got proper NEW-TAPE worker0 $handle") or die;
718 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
719 "got PARTDONE for filenum 1") or die;
720 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
721 "got PARTDONE for filenum 2") or die;
722 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 640 "\[sec [\d.]+ kb 640 kps [\d.]+\]"$/,
723 "got PARTDONE for filenum 3") or die;
724 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 4 96 "\[sec [\d.]+ kb 96 kps [\d.]+\]"$/,
725 "got PARTDONE for filenum 4") or die;
726 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
727 "got DUMPER-STATUS request") or die;
728 taper_cmd("FAILED worker0 $handle");
729 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 2016 kps [\d.]+\]" "" ""$/,
735 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
736 qr(^PART taper TESTCONF01 1 localhost /sbin $datestamp 1/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
737 qr(^PART taper TESTCONF01 2 localhost /sbin $datestamp 2/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
738 qr(^PART taper TESTCONF01 3 localhost /sbin $datestamp 3/-1 0 \[sec [\d.]+ kb 640 kps [\d.]+\]$),
739 qr(^PART taper TESTCONF01 4 localhost /sbin $datestamp 4/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+\]$),
740 qr(^PARTIAL taper localhost /sbin $datestamp 4 0 \[sec [\d.]+ kb 2016 kps [\d.]+\]$), # note no error message
741 qr(^INFO taper tape TESTCONF01 kb 2016 fm 4 \[OK\]$),
742 ], "DUMPER_STATUS => FAILED logged correctly");
745 # Test a sequence of writes to the same set of tapes
747 $handle = "33-11111";
748 $datestamp = "20090101010000";
749 run_taper(1024, "first in a sequence");
750 like(taper_reply, qr/^TAPER-OK worker0$/,
751 "got TAPER-OK") or die;
752 make_holding_file(500000, "localhost", "/u01");
753 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1412");
754 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
755 "got REQUEST-NEW-TAPE worker0 $handle") or die;
756 taper_cmd("START-SCAN worker0 $handle");
757 taper_cmd("NEW-TAPE worker0 $handle");
758 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
759 "got proper NEW-TAPE worker0 $handle") or die;
760 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1412\]"$/,
761 "got PARTDONE for filenum 1") or die;
762 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 232 "\[sec [\d.]+ kb 232 kps [\d.]+ orig-kb 1412\]"$/,
763 "got PARTDONE for filenum 2") or die;
764 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 488 kps [\d.]+ orig-kb 1412\]" "" ""$/,
766 $handle = "33-22222";
767 make_holding_file(614400, "localhost", "/u02");
768 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1512");
769 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]"$/,
770 "got PARTDONE for filenum 3") or die;
771 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
772 "got REQUEST-NEW-TAPE worker0 $handle") or die;
773 taper_cmd("START-SCAN worker0 $handle");
774 taper_cmd("NEW-TAPE worker0 $handle");
775 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
776 "got proper NEW-TAPE worker0 $handle") or die;
777 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]"$/,
778 "got PARTDONE for filenum 1 on second tape") or die;
779 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1512\]"$/,
780 "got PARTDONE for filenum 2 on second tape") or die;
781 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1512\]" "" ""$/,
787 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
788 qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1412\]$),
789 qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 232 kps [\d.]+ orig-kb 1412\]$),
790 qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 488 kps [\d.]+ orig-kb 1412\]$),
791 qr(^PART taper TESTCONF01 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]$),
792 qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+ orig-kb 1512\] "No space left on device"$),
793 qr(^INFO taper Will request retry of failed split part\.$),
794 qr(^INFO taper tape TESTCONF01 kb 744 fm 4 \[OK\]$),
795 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
796 qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1512\]$),
797 qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1512\]$),
798 qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1512\]$),
799 qr(^INFO taper tape TESTCONF02 kb 344 fm 2 \[OK\]$),
800 ], "first taper invocation in sequence logged correctly");
803 $handle = "33-33333";
804 $datestamp = "20090202020000";
805 run_taper(1024, "second in a sequence", keep_config => 1);
806 like(taper_reply, qr/^TAPER-OK worker0$/,
807 "got TAPER-OK") or die;
808 make_holding_file(300000, "localhost", "/u01");
809 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
810 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
811 "got REQUEST-NEW-TAPE worker0 $handle") or die;
812 taper_cmd("START-SCAN worker0 $handle");
813 taper_cmd("NEW-TAPE worker0 $handle");
814 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF03$/,
815 "got proper NEW-TAPE worker0 $handle") or die;
816 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
817 "got PARTDONE for filenum 1") or die;
818 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 2 36 "\[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]"$/,
819 "got PARTDONE for filenum 2") or die;
820 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]" "" ""$/,
822 $handle = "33-44444";
823 make_holding_file(614400, "localhost", "/u02");
824 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
825 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
826 "got PARTDONE for filenum 3") or die;
827 like(taper_reply, qr/^PARTDONE $handle TESTCONF03 4 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
828 "got PARTDONE for filenum 4") or die;
829 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
830 "got REQUEST-NEW-TAPE worker0 $handle") or die;
831 taper_cmd("START-SCAN worker0 $handle");
832 taper_cmd("NEW-TAPE worker0 $handle");
833 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
834 "got proper NEW-TAPE worker0 $handle") or die;
835 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]"$/,
836 "got PARTDONE for filenum 1 on second tape") or die;
837 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]" "" ""$/,
843 qr(^START taper datestamp $datestamp label TESTCONF03 tape 1$),
844 qr(^PART taper TESTCONF03 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
845 qr(^PART taper TESTCONF03 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]$),
846 qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]$),
847 qr(^PART taper TESTCONF03 3 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
848 qr(^PART taper TESTCONF03 4 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
849 qr(^PARTPARTIAL taper TESTCONF03 5 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 0 kps [\d.]+ orig-kb 1712\] "No space left on device"$),
850 qr(^INFO taper Will request retry of failed split part\.$),
851 qr(^INFO taper tape TESTCONF03 kb 804 fm 5 \[OK\]$),
852 qr(^START taper datestamp $datestamp label TESTCONF01 tape 2$),
853 qr(^PART taper TESTCONF01 1 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]$),
854 qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]$),
855 qr(^INFO taper tape TESTCONF01 kb 88 fm 1 \[OK\]$),
856 ], "second taper invocation in sequence logged correctly");
860 # test failure to overwrite a tape label
862 $handle = "33-55555";
863 $datestamp = "20090303030000";
864 run_taper(1024, "failure to overwrite a volume", keep_config => 1);
865 like(taper_reply, qr/^TAPER-OK worker0$/,
866 "got TAPER-OK") or die;
867 make_holding_file(32768, "localhost", "/u03");
868 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u03 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1812");
869 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
870 "got REQUEST-NEW-TAPE worker0 $handle") or die;
871 # we've secretly replaced the tape in slot 1 with a read-only tape.. let's see
872 # if anyone can tell the difference!
873 chmod(0555, Installcheck::Run::vtape_dir(2));
874 taper_cmd("START-SCAN worker0 $handle");
875 taper_cmd("NEW-TAPE worker0 $handle");
876 # NO-NEW-TAPE indicates it did *not* overwrite the tape
877 like(taper_reply, qr/^NO-NEW-TAPE $handle$/,
878 "got proper NO-NEW-TAPE worker0 $handle"); # no "die" here, so we can restore perms
879 chmod(0755, Installcheck::Run::vtape_dir(2));
880 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
881 "got REQUEST-NEW-TAPE worker0 $handle") or die;
882 taper_cmd("NO-NEW-TAPE worker0 $handle \"sorry\"");
883 like(taper_reply, qr/^FAILED $handle INPUT-GOOD TAPE-ERROR "" "?sorry"?.*$/,
884 "got FAILED") or die;
888 # (logs aren't that interesting here - filled with VFS-specific error messages)
890 # TODO: simulate an "erased" tape, to which taper should reply with "NEW-TAPE worker0 $handle" and
891 # immediately REQUEST-NEW-TAPE. I can't see a way to make the VFS device erase a
892 # volume without start_device succeeding.
895 # A run with a bogus tapedev/tpchanger
896 $handle = "44-11111";
897 $datestamp = "20070102030405";
898 run_taper(4096, "no tapedev", notapedev => 1);
899 like(taper_reply, qr/^TAPE-ERROR SETUP "You must specify one of 'tapedev' or 'tpchanger'"$/,
900 "got TAPE-ERROR") or die;
904 # A run with 2 workers
905 my $handle0 = "66-00000";
906 my $handle1 = "66-11111";
907 $datestamp = "20090202020000";
908 run_taper(1024, "with 2 workers", new_vtapes => 1);
909 like(taper_reply, qr/^TAPER-OK worker0$/,
910 "got TAPER-OK") or die;
911 taper_cmd("START-TAPER worker1 $datestamp");
912 like(taper_reply, qr/^TAPER-OK worker1$/,
913 "got TAPER-OK") or die;
914 make_holding_file(300000, "localhost", "/u01");
915 taper_cmd("FILE-WRITE worker0 $handle0 \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
916 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle0$/,
917 "got REQUEST-NEW-TAPE worker0 $handle0") or die;
918 taper_cmd("START-SCAN worker0 $handle0");
919 taper_cmd("NEW-TAPE worker0 $handle0");
920 like(taper_reply, qr/^NEW-TAPE $handle0 TESTCONF01$/,
921 "got proper NEW-TAPE worker0 $handle0") or die;
922 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
923 "got PARTDONE for filenum 1") or die;
924 like(taper_reply, qr/^PARTDONE $handle0 TESTCONF01 2 36 "\[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]"$/,
925 "got PARTDONE for filenum 2") or die;
926 like(taper_reply, qr/^DONE $handle0 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]" "" ""$/,
928 make_holding_file(614400, "localhost", "/u02");
929 taper_cmd("FILE-WRITE worker1 $handle1 \"$test_filename\" localhost /u02 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1712");
930 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle1$/,
931 "got REQUEST-NEW-TAPE worker1 $handle1") or die;
932 taper_cmd("START-SCAN worker1 $handle1");
933 taper_cmd("NEW-TAPE worker1 $handle1");
934 like(taper_reply, qr/^NEW-TAPE $handle1 TESTCONF02$/,
935 "got proper NEW-TAPE worker1 $handle1") or die;
936 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
937 "got PARTDONE for filenum 1 on second tape") or die;
938 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 2 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]"$/,
939 "got PARTDONE for filenum 2 on second tape") or die;
940 like(taper_reply, qr/^PARTDONE $handle1 TESTCONF02 3 88 "\[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]"$/,
941 "got PARTDONE for filenum 3 on second tape") or die;
942 like(taper_reply, qr/^DONE $handle1 INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]" "" ""$/,
948 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
949 qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
950 qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 36 kps [\d.]+ orig-kb 1612\]$),
951 qr(^DONE taper localhost /u01 $datestamp 2 0 \[sec [\d.]+ kb 292 kps [\d.]+ orig-kb 1612\]$),
952 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
953 qr(^PART taper TESTCONF02 1 localhost /u02 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
954 qr(^PART taper TESTCONF02 2 localhost /u02 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1712\]$),
955 qr(^PART taper TESTCONF02 3 localhost /u02 $datestamp 3/-1 0 \[sec [\d.]+ kb 88 kps [\d.]+ orig-kb 1712\]$),
956 qr(^DONE taper localhost /u02 $datestamp 3 0 \[sec [\d.]+ kb 600 kps [\d.]+ orig-kb 1712\]$),
957 qr(^INFO taper tape TESTCONF01 kb 292 fm 2 \[OK\]$),
958 qr(^INFO taper tape TESTCONF02 kb 600 fm 3 \[OK\]$),
959 ], "two workers logged correctly");
963 # A run with 2 workers and a take_scribe
964 $handle = "66-22222";
965 $datestamp = "20090202020000";
966 run_taper(1024, "with 2 workers and a take_scribe", new_vtapes => 1);
967 like(taper_reply, qr/^TAPER-OK worker0$/,
968 "got TAPER-OK") or die;
969 taper_cmd("START-TAPER worker1 $datestamp");
970 like(taper_reply, qr/^TAPER-OK worker1$/,
971 "got TAPER-OK") or die;
972 make_holding_file(1000000, "localhost", "/u01");
973 taper_cmd("FILE-WRITE worker0 $handle \"$test_filename\" localhost /u01 0 $datestamp 262144 \"\" \"\" \"\" \"\" \"\" \"\" \"\" 1612");
974 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
975 "got REQUEST-NEW-TAPE worker0 $handle") or die;
976 taper_cmd("START-SCAN worker0 $handle");
977 taper_cmd("NEW-TAPE worker0 $handle");
978 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
979 "got proper NEW-TAPE worker0 $handle") or die;
980 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
981 "got PARTDONE for filenum 1") or die;
982 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
983 "got PARTDONE for filenum 2") or die;
984 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 256 "\[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]"$/,
985 "got PARTDONE for filenum 3") or die;
986 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
987 "got REQUEST-NEW-TAPE worker0 $handle") or die;
988 taper_cmd("TAKE-SCRIBE-FROM worker0 $handle worker1");
989 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
990 "got REQUEST-NEW-TAPE worker0 $handle") or die;
991 taper_cmd("START-SCAN worker0 $handle");
992 taper_cmd("NEW-TAPE worker0 $handle");
993 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
994 "got proper NEW-TAPE worker0 $handle") or die;
995 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 208 "\[sec [\d.]+ kb 208 kps [\d.]+ orig-kb 1612\]"$/,
996 "got PARTDONE for filenum 4") or die;
997 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 976 kps [\d.]+ orig-kb 1612\]" "" ""$/,
1003 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1004 qr(^PART taper TESTCONF01 1 localhost /u01 $datestamp 1/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1005 qr(^PART taper TESTCONF01 2 localhost /u01 $datestamp 2/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1006 qr(^PART taper TESTCONF01 3 localhost /u01 $datestamp 3/-1 0 \[sec [\d.]+ kb 256 kps [\d.]+ orig-kb 1612\]$),
1007 qr(^PARTPARTIAL taper TESTCONF01 4 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ kb 96 kps [\d.]+ orig-kb 1612\] \"No space left on device\"$),
1008 qr(^INFO taper Will request retry of failed split part.$),
1009 qr(^INFO taper tape TESTCONF01 kb 768 fm 4 \[OK\]$),
1010 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1011 qr(^PART taper TESTCONF02 1 localhost /u01 $datestamp 4/-1 0 \[sec [\d.]+ kb 208 kps [\d.]+ orig-kb 1612\]$),
1012 qr(^DONE taper localhost /u01 $datestamp 4 0 \[sec [\d.]+ kb 976 kps [\d.]+ orig-kb 1612\]$),
1013 qr(^INFO taper tape TESTCONF02 kb 208 fm 1 \[OK\]$),
1014 ], "TAKE-SCRIBE logged correctly");
1018 # Test with NDMP device (DirectTCP)
1021 skip "not built with NDMP", 33 unless Amanda::Util::built_with_component("ndmp");
1023 my $ndmp = Installcheck::Mock::NdmpServer->new(tape_limit => 1024*1024);
1024 my $ndmp_port = $ndmp->{'port'};
1025 my $drive = $ndmp->{'drive'};
1027 $handle = "55-11111";
1028 $datestamp = "19780615010305";
1029 run_taper(4096, "multipart directtcp PORT-WRITE",
1030 ndmp_server => $ndmp);
1031 like(taper_reply, qr/^TAPER-OK worker0$/,
1032 "got TAPER-OK") or die;
1033 # note that, with the addition of the new splitting params, this does the "sensible"
1034 # thing and uses the tape_splitsize, not the fallback_splitsize (this is a change from
1036 taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 393216 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1037 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1038 "got PORT with data address");
1039 write_to_port($last_taper_reply, 1230*1024, "localhost", "/var", 0);
1040 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1041 "got REQUEST-NEW-TAPE worker0 $handle") or die;
1042 taper_cmd("START-SCAN worker0 $handle");
1043 taper_cmd("NEW-TAPE worker0 $handle");
1044 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1045 "got proper NEW-TAPE worker0 $handle") or die;
1046 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1047 "got PARTDONE for part 1") or die;
1048 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1049 "got PARTDONE for part 2") or die;
1050 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 3 64 "\[sec [\d.]+ kb 64 kps [\d.]+\]"$/,
1051 "got PARTDONE for part 3 (short part)") or die;
1052 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1053 "got REQUEST-NEW-TAPE worker0 $handle") or die;
1054 taper_cmd("START-SCAN worker0 $handle");
1055 taper_cmd("NEW-TAPE worker0 $handle");
1056 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1057 "got proper NEW-TAPE worker0 $handle") or die;
1058 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1059 "got PARTDONE for part 4") or die;
1060 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 32 "\[sec [\d.]+ kb 32 kps [\d.]+\]"$/,
1061 "got PARTDONE for part 5") or die;
1062 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1063 "got DUMPER-STATUS request") or die;
1064 taper_cmd("DONE worker0 $handle 1912");
1065 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1248 kps [\d.]+ orig-kb 1912\]" "" ""$/,
1067 $handle = "55-22222";
1068 taper_cmd("PORT-WRITE worker0 $handle localhost /etc 0 $datestamp 524288 \"\" 393216 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1069 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1070 "got PORT with data address");
1071 write_to_port($last_taper_reply, 300*1024, "localhost", "/etc", 0);
1072 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 3 320 "\[sec [\d.]+ kb 320 kps [\d.]+\]"$/,
1073 "got PARTDONE for part 1") or die;
1074 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1075 "got DUMPER-STATUS request") or die;
1076 taper_cmd("DONE worker0 $handle 2012");
1077 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 320 kps [\d.]+ orig-kb 2012\]" "" ""$/,
1083 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1084 qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1085 qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1086 qr(^PART taper TESTCONF01 3 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 64 kps [\d.]+\]$),
1087 # note no "Will retry.."
1088 qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1089 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1090 qr(^PART taper TESTCONF02 1 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1091 qr(^PART taper TESTCONF02 2 localhost /var $datestamp 5/-1 0 \[sec [\d.]+ kb 32 kps [\d.]+\]$),
1092 qr(^DONE taper localhost /var $datestamp 5 0 \[sec [\d.]+ kb 1248 kps [\d.]+ orig-kb 1912\]$),
1093 qr(^PART taper TESTCONF02 3 localhost /etc $datestamp 1/-1 0 \[sec [\d.]+ kb 320 kps [\d.]+\]$),
1094 qr(^DONE taper localhost /etc $datestamp 1 0 \[sec [\d.]+ kb 320 kps [\d.]+ orig-kb 2012\]$),
1095 qr(^INFO taper tape TESTCONF02 kb 736 fm 3 \[OK\]$),
1096 ], "multipart directtcp PORT-WRITE logged correctly");
1098 $handle = "55-33333";
1099 $datestamp = "19780615010305";
1100 run_taper(4096, "multipart directtcp PORT-WRITE, with a zero-byte part",
1101 ndmp_server => $ndmp);
1102 like(taper_reply, qr/^TAPER-OK worker0$/,
1103 "got TAPER-OK") or die;
1104 # use a different part size this time, to hit EOM "on the head"
1105 taper_cmd("PORT-WRITE worker0 $handle localhost /var 0 $datestamp 425984 \"\" 327680 \"\" \"\" \"\" \"\" \"\" DIRECTTCP");
1106 like(taper_reply, qr/^PORT worker0 $handle (\d+) "?(\d+\.\d+\.\d+\.\d+:\d+;?)+"?$/,
1107 "got PORT with data address");
1108 write_to_port($last_taper_reply, 1632*1024, "localhost", "/var", 0);
1109 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1110 "got REQUEST-NEW-TAPE worker0 $handle") or die;
1111 taper_cmd("START-SCAN worker0 $handle");
1112 taper_cmd("NEW-TAPE worker0 $handle");
1113 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF01$/,
1114 "got proper NEW-TAPE worker0 $handle") or die;
1115 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 1 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1116 "got PARTDONE for part 1") or die;
1117 like(taper_reply, qr/^PARTDONE $handle TESTCONF01 2 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1118 "got PARTDONE for part 2") or die;
1119 # note: zero-byte part is not reported as PARTDONE
1120 like(taper_reply, qr/^REQUEST-NEW-TAPE $handle$/,
1121 "got REQUEST-NEW-TAPE worker0 $handle") or die;
1122 taper_cmd("START-SCAN worker0 $handle");
1123 taper_cmd("NEW-TAPE worker0 $handle");
1124 like(taper_reply, qr/^NEW-TAPE $handle TESTCONF02$/,
1125 "got proper NEW-TAPE worker0 $handle") or die;
1126 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 1 416 "\[sec [\d.]+ kb 416 kps [\d.]+\]"$/,
1127 "got PARTDONE for part 3") or die;
1128 like(taper_reply, qr/^PARTDONE $handle TESTCONF02 2 384 "\[sec [\d.]+ kb 384 kps [\d.]+\]"$/,
1129 "got PARTDONE for part 4") or die;
1130 like(taper_reply, qr/^DUMPER-STATUS $handle$/,
1131 "got DUMPER-STATUS request") or die;
1132 taper_cmd("DONE worker0 $handle 2112");
1133 like(taper_reply, qr/^DONE $handle INPUT-GOOD TAPE-GOOD "\[sec [\d.]+ kb 1632 kps [\d.]+ orig-kb 2112\]" "" ""$/,
1139 qr(^START taper datestamp $datestamp label TESTCONF01 tape 1$),
1140 qr(^PART taper TESTCONF01 1 localhost /var $datestamp 1/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1141 qr(^PART taper TESTCONF01 2 localhost /var $datestamp 2/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1142 # Note: zero-byte part is not logged, but is counted in this INFO line's 'fm' field
1143 qr(^INFO taper tape TESTCONF01 kb 832 fm 3 \[OK\]$),
1144 qr(^START taper datestamp $datestamp label TESTCONF02 tape 2$),
1145 qr(^PART taper TESTCONF02 1 localhost /var $datestamp 3/-1 0 \[sec [\d.]+ kb 416 kps [\d.]+\]$),
1146 qr(^PART taper TESTCONF02 2 localhost /var $datestamp 4/-1 0 \[sec [\d.]+ kb 384 kps [\d.]+\]$),
1147 qr(^DONE taper localhost /var $datestamp 4 0 \[sec [\d.]+ kb 1632 kps [\d.]+ orig-kb 2112\]$),
1148 qr(^INFO taper tape TESTCONF02 kb 800 fm 2 \[OK\]$),
1149 ], "multipart directtcp PORT-WRITE with a zero-byte part logged correctly");
1153 } # end of ndmp SKIP