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

   1 # Copyright (c) 2007, 2008, 2009, 2010 Zmanda, Inc.  All Rights Reserved.
   2 #
   3 # This program is free software; you can redistribute it and/or modify it
   4 # under the terms of the GNU General Public License version 2 as published
   5 # by the Free Software Foundation.
   6 #
   7 # This program is distributed in the hope that it will be useful, but
   8 # WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
   9 # or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  10 # for more details.
  11 #
  12 # You should have received a copy of the GNU General Public License along
  13 # with this program; if not, write to the Free Software Foundation, Inc.,
  14 # 59 Temple Place, Suite 330, Boston, MA  02111-1307 USA
  15 #
  16 # Contact information: Zmanda Inc, 465 S. Mathilda Ave., Suite 300
  17 # Sunnyvale, CA 94086, USA, or: http://www.zmanda.com
  18
  19 use Test::More tests => 35;
  20 use File::Path;
  21 use strict;
  22
  23 use lib "@amperldir@";
  24 use Installcheck;
  25 use Installcheck::Config;
  26 use Data::Dumper;
  27 use Amanda::Paths;
  28 use Amanda::Tapelist;
  29 use Amanda::Cmdline;
  30 use Amanda::Util;
  31 use Amanda::Debug qw( :logging );
  32 use Amanda::Logfile qw(:logtype_t :program_t open_logfile get_logline
  33                 close_logfile log_add $amanda_log_trace_log );
  34 use Amanda::Config qw( :init :getconf config_dir_relative );
  35
  36 Amanda::Debug::dbopen("installcheck");
  37
  38 my $log_filename = "$Installcheck::TMP/Amanda_Logfile_test.log";
  39
  40 # write a logfile and return the filename
  41 sub write_logfile {
  42     my ($contents) = @_;
  43
  44     if (!-e $Installcheck::TMP) {
  45         mkpath($Installcheck::TMP);
  46     }
  47
  48     open my $logfile, ">", $log_filename or die("Could not create temporary log file '$log_filename': $!");
  49     print $logfile $contents;
  50     close $logfile;
  51
  52     return $log_filename;
  53 }
  54
  55 ####
  56 ## RAW LOGFILE ACCESS
  57
  58 my $logfile;
  59 my $logdata;
  60
  61 ##
  62 # Test out the constant functions
  63
  64 is(logtype_t_to_string($L_MARKER), "L_MARKER", "logtype_t_to_string works");
  65 is(program_t_to_string($P_DRIVER), "P_DRIVER", "program_t_to_string works");
  66
  67 ##
  68 # Regression test for previously missing program types
  69 is( program_t_to_string($P_AMDUMP),
  70     "P_AMDUMP", "program type for amdump defined" );
  71 is( program_t_to_string($P_AMIDXTAPED),
  72     "P_AMIDXTAPED", "program type for amidxtaped defined" );
  73 is( program_t_to_string($P_AMFETCHDUMP),
  74     "P_AMFETCHDUMP", "program type for amfetchdump defined" );
  75 is( program_t_to_string($P_AMCHECKDUMP),
  76     "P_AMCHECKDUMP", "program type for amcheckdump defined" );
  77
  78 ##
  79 # Test a simple logfile
  80
  81 $logdata = <<END;
  82 START planner date 20071026183200
  83 END
  84
  85 $logfile = open_logfile(write_logfile($logdata));
  86 ok($logfile, "can open a simple logfile");
  87 is_deeply([ get_logline($logfile) ],
  88           [ $L_START, $P_PLANNER, "date 20071026183200" ],
  89           "reads START line correctly");
  90 ok(!get_logline($logfile), "no second line");
  91 close_logfile($logfile);
  92
  93 ##
  94 # Test continuation lines
  95
  96 $logdata = <<END;
  97 INFO chunker line1
  98   line2
  99 END
 100
 101 $logfile = open_logfile(write_logfile($logdata));
 102 ok($logfile, "can open a logfile containing continuation lines");
 103 is_deeply([ get_logline($logfile) ],
 104           [ $L_INFO, $P_CHUNKER, "line1" ],
 105           "can read INFO line");
 106 is_deeply([ get_logline($logfile) ],
 107           [ $L_CONT, $P_CHUNKER, "line2" ],
 108           "can read continuation line");
 109 ok(!get_logline($logfile), "no third line");
 110 close_logfile($logfile);
 111
 112 ##
 113 # Test skipping blank lines
 114
 115 # (retain the two blank lines in the following:)
 116 $logdata = <<END;
 117
 118 STATS taper foo
 119
 120 END
 121
 122 $logfile = open_logfile(write_logfile($logdata));
 123 ok($logfile, "can open a logfile containing blank lines");
 124 is_deeply([ get_logline($logfile) ],
 125           [ $L_STATS, $P_TAPER, "foo" ],
 126           "reads non-blank line correctly");
 127 ok(!get_logline($logfile), "no second line");
 128 close_logfile($logfile);
 129
 130 ##
 131 # Test BOGUS values and short lines
 132
 133 $logdata = <<END;
 134 SOMETHINGWEIRD somerandomprog bar
 135 MARKER amflush
 136 MARKER amflush put something in curstr
 137 PART
 138 END
 139
 140 $logfile = open_logfile(write_logfile($logdata));
 141 ok($logfile, "can open a logfile containing bogus entries");
 142 is_deeply([ get_logline($logfile) ],
 143           [ $L_BOGUS, $P_UNKNOWN, "bar" ],
 144           "can read line with bogus program and logtype");
 145 is_deeply([ get_logline($logfile) ],
 146           [ $L_MARKER, $P_AMFLUSH, "" ],
 147           "can read line with an empty string");
 148 ok(get_logline($logfile), "can read third line (to fill in curstr with some text)");
 149 is_deeply([ get_logline($logfile) ],
 150           [ $L_PART, $P_UNKNOWN, "" ],
 151           "can read a one-word line, with P_UNKNOWN");
 152 ok(!get_logline($logfile), "no next line");
 153 close_logfile($logfile);
 154
 155 ## HIGHER-LEVEL FUNCTIONS
 156
 157 # a utility function for is_deeply checks, below.  Converts a hash to
 158 # an array, for more succinct comparisons
 159 sub res2arr {
 160     my ($res) = @_;
 161     return [
 162         $res->{'timestamp'},
 163         $res->{'hostname'},
 164         $res->{'diskname'},
 165         "$res->{'level'}",
 166         $res->{'label'},
 167         "$res->{'filenum'}",
 168         $res->{'status'},
 169         $res->{'dump_status'},
 170         $res->{'message'},
 171         "$res->{'partnum'}",
 172         "$res->{'totalparts'}"
 173     ];
 174 }
 175
 176 # set up a basic config
 177 my $testconf = Installcheck::Config->new();
 178 $testconf->add_param("tapecycle", "20");
 179 $testconf->write();
 180
 181 # load the config
 182 config_init($CONFIG_INIT_EXPLICIT_NAME, "TESTCONF") == $CFGERR_OK
 183     or die("Could not load config");
 184 my $tapelist = config_dir_relative("tapelist");
 185 my $logdir = $testconf->{'logdir'};
 186
 187 # test log_add
 188 {
 189     my $filename = "$logdir/log";
 190
 191     -f "$filename" and unlink("$filename");
 192     log_add($L_INFO, "This is my info");
 193
 194     open(my $fh, "<", $filename) or die("open $filename: $!");
 195     my $logdata = do { local $/; <$fh> };
 196     close($fh);
 197
 198     like($logdata, qr/^INFO Amanda_Logfile This is my info/, "log_add works");
 199 }
 200
 201 # set up and read the tapelist (we don't use Amanda::Tapelist to write this,
 202 # in case it's broken)
 203 open my $tlf, ">", $tapelist or die("Could not write tapelist");
 204 print $tlf "20071111010002 TESTCONF006 reuse\n";
 205 print $tlf "20071110010002 TESTCONF005 reuse\n";
 206 print $tlf "20071109010002 TESTCONF004 reuse\n";
 207 print $tlf "20071109010002 TESTCONF003 reuse\n";
 208 print $tlf "20071109010002 TESTCONF002 reuse\n";
 209 print $tlf "20071108010001 TESTCONF001 reuse\n";
 210 close $tlf;
 211 Amanda::Tapelist::read_tapelist($tapelist);
 212
 213 # set up a number of logfiles in logdir.
 214 my $logf;
 215
 216 # (an old log file that should be ignored)
 217 open $logf, ">", "$logdir/log.20071106010002.0" or die("Could not write logfile");
 218 print $logf "START taper datestamp 20071107010002 label TESTCONF017 tape 1\n";
 219 close $logf;
 220
 221 # (a logfile with two tapes)
 222 open $logf, ">", "$logdir/log.20071106010002.0" or die("Could not write logfile");
 223 print $logf "START taper datestamp 20071106010002 label TESTCONF018 tape 1\n";
 224 print $logf "START taper datestamp 20071106010002 label TESTCONF019 tape 2\n";
 225 close $logf;
 226
 227 open $logf, ">", "$logdir/log.20071108010001.0" or die("Could not write logfile");
 228 print $logf "START taper datestamp 20071108010001 label TESTCONF001 tape 1\n";
 229 close $logf;
 230
 231 # a logfile with some detail, to run search_logfile against
 232 open $logf, ">", "$logdir/log.20071109010002.0" or die("Could not write logfile");
 233 print $logf <<EOF;
 234 START taper datestamp 20071109010002 label TESTCONF002 tape 1
 235 PART taper TESTCONF002 1 clihost /usr 20071109010002 1 0 [regular single part PART]
 236 DONE taper clihost /usr 20071109010002 1 0 [regular single part DONE]
 237 PART taper TESTCONF002 2 clihost "/my documents" 20071109010002 1 0 [diskname quoting]
 238 DONE taper clihost "/my documents" 20071109010002 1 0 [diskname quoting]
 239 PART taper TESTCONF002 3 thatbox /var 1 [regular 'old style' PART]
 240 DONE taper thatbox /var 1 [regular 'old style' DONE]
 241 PART taper TESTCONF002 4 clihost /home 20071109010002 1/5 0 [multi-part dump]
 242 PART taper TESTCONF002 5 clihost /home 20071109010002 2/5 0 [multi-part dump]
 243 PART taper TESTCONF002 6 clihost /home 20071109010002 3/5 0 [multi-part dump]
 244 PART taper TESTCONF002 7 clihost /home 20071109010002 4/5 0 [multi-part dump]
 245 PART taper TESTCONF002 8 clihost /home 20071109010002 5/5 0 [multi-part dump]
 246 DONE taper clihost /home 20071109010002 5 0 [multi-part dump]
 247 PART taper TESTCONF002 9 thatbox /u_lose 20071109010002 1/4 2 [multi-part failure]
 248 PART taper TESTCONF002 10 thatbox /u_lose 20071109010002 2/4 2 [multi-part failure]
 249 PARTPARTIAL taper TESTCONF002 11 thatbox /u_lose 20071109010002  3/4 2 [multi-part retry]
 250 START taper datestamp 20071109010002 label TESTCONF003 tape 1
 251 PART taper TESTCONF003 1 thatbox /u_lose 20071109010002 3/4 2 [multi-part failure]
 252 FAIL taper thatbox /u_lose 20071109010002 2 "Oh no!"
 253 PART taper TESTCONF003 2 thatbox /u_win 20071109010002 1/4 3 [multi-part retry]
 254 PART taper TESTCONF003 3 thatbox /u_win 20071109010002 2/4 3 [multi-part retry]
 255 PARTPARTIAL taper TESTCONF003 4 thatbox /u_win 20071109010002  3/4 3 [multi-part retry]
 256 START taper datestamp 20071109010002 label TESTCONF004 tape 1
 257 PART taper TESTCONF004 1 thatbox /u_win 20071109010002 3/4 3 [multi-part retry]
 258 PART taper TESTCONF004 2 thatbox /u_win 20071109010002 4/4 3 [multi-part retry]
 259 DONE taper thatbox /u_win 20071109010002 4 3 [multi-part retry]
 260 EOF
 261 close $logf;
 262
 263 # "old-style amflush log"
 264 open $logf, ">", "$logdir/log.20071110010002.amflush" or die("Could not write logfile");
 265 print $logf "START taper datestamp 20071110010002 label TESTCONF005 tape 1\n";
 266 close $logf;
 267
 268 # "old-style main log"
 269 open $logf, ">", "$logdir/log.20071111010002" or die("Could not write logfile");
 270 print $logf "START taper datestamp 20071111010002 label TESTCONF006 tape 1\n";
 271 close $logf;
 272
 273 is_deeply([ Amanda::Logfile::find_log() ],
 274           [ "log.20071111010002", "log.20071110010002.amflush",
 275             "log.20071109010002.0", "log.20071108010001.0" ],
 276           "find_log returns correct logfiles in the correct order");
 277
 278 my @results;
 279 my @results_arr;
 280
 281 @results = Amanda::Logfile::search_logfile(undef, "20071109010002",
 282                                            "$logdir/log.20071109010002.0", 1);
 283 is($#results+1, 17, "search_logfile returned 17 results");
 284
 285 # sort by filenum so we can compare each to what it should be
 286 @results = sort { $a->{'label'} cmp $b->{'label'} ||
 287                   $a->{'filenum'} <=> $b->{'filenum'} } @results;
 288
 289 # and convert the hashes to arrays for easy comparison
 290 @results_arr = map { res2arr($_) } @results;
 291 is_deeply(\@results_arr,
 292         [
 293           [ '20071109010002', 'clihost', '/usr',            0, 'TESTCONF002', 1,  'OK',       'OK',   '',         1, 1 ],
 294           [ '20071109010002', 'clihost', '/my documents',   0, 'TESTCONF002', 2,  'OK',       'OK',   '',         1, 1 ],
 295           [ '20071109010002', 'thatbox', '/var',            1, 'TESTCONF002', 3,  'OK',       'OK',   '',         1, 1 ],
 296           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 4,  'OK',       'OK',   '',         1, 5 ],
 297           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 5,  'OK',       'OK',   '',         2, 5 ],
 298           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 6,  'OK',       'OK',   '',         3, 5 ],
 299           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 7,  'OK',       'OK',   '',         4, 5 ],
 300           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 8,  'OK',       'OK',   '',         5, 5 ],
 301           [ '20071109010002', 'thatbox', '/u_lose',         2, 'TESTCONF002', 9,  'OK',       'FAIL', '"Oh no!"', 1, 4 ],
 302           [ '20071109010002', 'thatbox', '/u_lose',         2, 'TESTCONF002', 10, 'OK',       'FAIL', '"Oh no!"', 2, 4 ],
 303           [ '20071109010002', 'thatbox', '/u_lose',         2, 'TESTCONF002', 11, 'PARTIAL',  'FAIL', '"Oh no!"', 3, 4 ],
 304           [ '20071109010002', 'thatbox', '/u_lose',         2, 'TESTCONF003', 1,  'OK',       'FAIL', '"Oh no!"', 3, 4 ],
 305           [ '20071109010002', 'thatbox', '/u_win',          3, 'TESTCONF003', 2,  'OK',       'OK',   '',         1, 4 ],
 306           [ '20071109010002', 'thatbox', '/u_win',          3, 'TESTCONF003', 3,  'OK',       'OK',   '',         2, 4 ],
 307           [ '20071109010002', 'thatbox', '/u_win',          3, 'TESTCONF003', 4,  'PARTIAL',  'OK',   '',         3, 4 ],
 308           [ '20071109010002', 'thatbox', '/u_win',          3, 'TESTCONF004', 1,  'OK',       'OK',   '',         3, 4 ],
 309           [ '20071109010002', 'thatbox', '/u_win',          3, 'TESTCONF004', 2,  'OK',       'OK',   '',         4, 4 ],
 310         ], "results are correct");
 311
 312 my @filtered;
 313 my @filtered_arr;
 314
 315 @filtered = Amanda::Logfile::dumps_match([@results], "thatbox", undef, undef, undef, 0);
 316 is($#filtered+1, 10, "ten results match 'thatbox'");
 317 @filtered = sort { $a->{'label'} cmp $b->{'label'} ||
 318                    $a->{'filenum'} <=> $b->{'filenum'} } @filtered;
 319
 320 @filtered_arr = map { res2arr($_) } @filtered;
 321
 322 is_deeply(\@filtered_arr,
 323         [
 324           [ '20071109010002', 'thatbox', '/var',      1, 'TESTCONF002', 3,  'OK',      'OK',   '',         1, 1 ],
 325           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 9,  'OK',      'FAIL', '"Oh no!"', 1, 4 ],
 326           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 10, 'OK',      'FAIL', '"Oh no!"', 2, 4 ],
 327           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 11, 'PARTIAL', 'FAIL', '"Oh no!"', 3, 4 ],
 328           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF003', 1,  'OK',      'FAIL', '"Oh no!"', 3, 4 ],
 329           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 2,  'OK',      'OK',   '',         1, 4 ],
 330           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 3,  'OK',      'OK',   '',         2, 4 ],
 331           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 4,  'PARTIAL', 'OK',   '',         3, 4 ],
 332           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF004', 1,  'OK',      'OK',   '',         3, 4 ],
 333           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF004', 2,  'OK',      'OK',   '',         4, 4 ],
 334         ], "results are correct");
 335
 336 @filtered = Amanda::Logfile::dumps_match([@results], "thatbox", "/var", undef, undef, 0);
 337 is($#filtered+1, 1, "only one result matches 'thatbox:/var'");
 338
 339 @filtered = Amanda::Logfile::dumps_match([@results], undef, undef, "20071109010002", undef, 0);
 340 is($#filtered+1, 17, "all 17 results match '20071109010002'");
 341
 342 @filtered = Amanda::Logfile::dumps_match([@results], undef, undef, "20071109010002", undef, 1);
 343 is($#filtered+1, 12, "of those, 12 results are 'OK'");
 344
 345 @filtered = Amanda::Logfile::dumps_match([@results], undef, undef, undef, "2", 0);
 346 is($#filtered+1, 4, "4 results are at level 2");
 347
 348 # test dumps_match_dumpspecs
 349
 350 my @dumpspecs;
 351
 352 @dumpspecs = Amanda::Cmdline::parse_dumpspecs(["thatbox", "/var"], 0);
 353 @filtered = Amanda::Logfile::dumps_match_dumpspecs([@results], [@dumpspecs], 0);
 354 is_deeply([ map { res2arr($_) } @filtered ],
 355         [
 356           [ '20071109010002', 'thatbox', '/var',            1, 'TESTCONF002', 3,  'OK', 'OK', '', 1, 1 ],
 357         ], "filter with dumpspecs 'thatbox /var'");
 358
 359 @dumpspecs = Amanda::Cmdline::parse_dumpspecs(["thatbox", "/var", "clihost"], 0);
 360 @filtered = Amanda::Logfile::dumps_match_dumpspecs([@results], [@dumpspecs], 0);
 361 @filtered = sort { $a->{'label'} cmp $b->{'label'} ||
 362                    $a->{'filenum'} <=> $b->{'filenum'} } @filtered;
 363 is_deeply([ map { res2arr($_) } @filtered ],
 364         [
 365           [ '20071109010002', 'clihost', '/usr',            0, 'TESTCONF002', 1,  'OK', 'OK', '', 1, 1 ],
 366           [ '20071109010002', 'clihost', '/my documents',   0, 'TESTCONF002', 2,  'OK', 'OK', '', 1, 1 ],
 367           [ '20071109010002', 'thatbox', '/var',            1, 'TESTCONF002', 3,  'OK', 'OK', '', 1, 1 ],
 368           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 4,  'OK', 'OK', '', 1, 5 ],
 369           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 5,  'OK', 'OK', '', 2, 5 ],
 370           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 6,  'OK', 'OK', '', 3, 5 ],
 371           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 7,  'OK', 'OK', '', 4, 5 ],
 372           [ '20071109010002', 'clihost', '/home',           0, 'TESTCONF002', 8,  'OK', 'OK', '', 5, 5 ],
 373         ], "filter with dumpspecs 'thatbox /var clihost' (union of two disjoint sets)");
 374
 375 # if multiple dumpspecs specify the same dump, it will be included in the output multiple times
 376 @dumpspecs = Amanda::Cmdline::parse_dumpspecs([".*", "/var", "thatbox"], 0);
 377 @filtered = Amanda::Logfile::dumps_match_dumpspecs([@results], [@dumpspecs], 0);
 378 @filtered = sort { $a->{'label'} cmp $b->{'label'} ||
 379                    $a->{'filenum'} <=> $b->{'filenum'} } @filtered;
 380 is_deeply([ map { res2arr($_) } @filtered ],
 381         [
 382           [ '20071109010002', 'thatbox', '/var',      1, 'TESTCONF002', 3,  'OK',      'OK'  , '',         1, 1 ],
 383           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 9,  'OK',      'FAIL', '"Oh no!"', 1, 4 ],
 384           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 10, 'OK',      'FAIL', '"Oh no!"', 2, 4 ],
 385           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF002', 11, 'PARTIAL', 'FAIL', '"Oh no!"', 3, 4 ],
 386           [ '20071109010002', 'thatbox', '/u_lose',   2, 'TESTCONF003', 1,  'OK',      'FAIL', '"Oh no!"', 3, 4 ],
 387           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 2,  'OK',      'OK'  , '',         1, 4 ],
 388           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 3,  'OK',      'OK'  , '',         2, 4 ],
 389           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF003', 4,  'PARTIAL', 'OK'  , '',         3, 4 ],
 390           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF004', 1,  'OK',      'OK'  , '',         3, 4 ],
 391           [ '20071109010002', 'thatbox', '/u_win',    3, 'TESTCONF004', 2,  'OK',      'OK'  , '',         4, 4 ],
 392         ], "filter with dumpspecs '.* /var thatbox' (union of two overlapping sets includes dupes)");
 393
 394 unlink($log_filename);
 395
 396 # search_holding_disk and match_* are tested via Amanda::DB::Catalog's installcheck