t/60-fsck.t

   1 # -*-perl-*-
   2 # some of the comments match the comments in MogileFS/Worker/Fsck.pm
   3 # _exactly_ for reference purposes
   4 use strict;
   5 use warnings;
   6 use Test::More;
   7 use FindBin qw($Bin);
   8 use Time::HiRes qw(sleep);
   9 use MogileFS::Server;
  10 use MogileFS::Test;
  11 use HTTP::Request;
  12 find_mogclient_or_skip();
  13 use MogileFS::Admin;
  14
  15 my $sto = eval { temp_store(); };
  16 if (!$sto) {
  17     plan skip_all => "Can't create temporary test database: $@";
  18     exit 0;
  19 }
  20
  21 use File::Temp;
  22 my %mogroot;
  23 $mogroot{1} = File::Temp::tempdir( CLEANUP => 1 );
  24 $mogroot{2} = File::Temp::tempdir( CLEANUP => 1 );
  25 $mogroot{3} = File::Temp::tempdir( CLEANUP => 1 );
  26 my $dev2host = { 1 => 1, 2 => 2, 3 => 2 };
  27 foreach (sort { $a <=> $b } keys %$dev2host) {
  28     my $root = $mogroot{$dev2host->{$_}};
  29     mkdir("$root/dev$_") or die "Failed to create dev$_ dir: $!";
  30 }
  31
  32 my $ms1 = create_mogstored("127.0.1.1", $mogroot{1});
  33 ok($ms1, "got mogstored1");
  34 my $ms2 = create_mogstored("127.0.1.2", $mogroot{2});
  35 ok($ms1, "got mogstored2");
  36
  37 while (! -e "$mogroot{1}/dev1/usage" ||
  38        ! -e "$mogroot{2}/dev2/usage" ||
  39        ! -e "$mogroot{2}/dev3/usage") {
  40     print "Waiting on usage...\n";
  41     sleep(.25);
  42 }
  43
  44 my $tmptrack = create_temp_tracker($sto);
  45 ok($tmptrack);
  46
  47 my $admin = IO::Socket::INET->new(PeerAddr => '127.0.0.1:7001');
  48 $admin or die "failed to create admin socket: $!";
  49 my $moga = MogileFS::Admin->new(hosts => [ "127.0.0.1:7001" ]);
  50 my $mogc = MogileFS::Client->new(
  51                                  domain => "testdom",
  52                                  hosts  => [ "127.0.0.1:7001" ],
  53                                  );
  54 my $be = $mogc->{backend}; # gross, reaching inside of MogileFS::Client
  55
  56 # test some basic commands to backend
  57 ok($tmptrack->mogadm("domain", "add", "testdom"), "created test domain");
  58 ok($tmptrack->mogadm("class", "add", "testdom", "2copies", "--mindevcount=2"), "created 2copies class in testdom");
  59 ok($tmptrack->mogadm("class", "add", "testdom", "1copy", "--mindevcount=1"), "created 1copy class in testdom");
  60
  61 ok($tmptrack->mogadm("host", "add", "hostA", "--ip=127.0.1.1", "--status=alive"), "created hostA");
  62 ok($tmptrack->mogadm("host", "add", "hostB", "--ip=127.0.1.2", "--status=alive"), "created hostB");
  63
  64 ok($tmptrack->mogadm("device", "add", "hostA", 1), "created dev1 on hostA");
  65 ok($tmptrack->mogadm("device", "add", "hostB", 2), "created dev2 on hostB");
  66
  67 sub wait_for_monitor {
  68     my $be = shift;
  69     my $was = $be->{timeout};  # can't use local on phash :(
  70     $be->{timeout} = 10;
  71     ok($be->do_request("clear_cache", {}), "waited for monitor")
  72         or die "Failed to wait for monitor";
  73     ok($be->do_request("clear_cache", {}), "waited for monitor")
  74         or die "Failed to wait for monitor";
  75     $be->{timeout} = $was;
  76 }
  77
  78 sub wait_for_empty_queue {
  79     my ($table, $dbh) = @_;
  80     my $limit = 600;
  81     my $delay = 0.1;
  82     my $i = $limit;
  83     my $count;
  84     while ($i > 0) {
  85         $count = $dbh->selectrow_array("SELECT COUNT(*) from $table");
  86         return if ($count == 0);
  87         sleep $delay;
  88     }
  89     my $time = $delay * $limit;
  90     die "$table is not empty after ${time}s!";
  91 }
  92
  93 sub full_fsck {
  94     my ($tmptrack, $dbh) = @_;
  95
  96     # this should help prevent race conditions:
  97     wait_for_empty_queue("file_to_queue", $dbh);
  98
  99     ok($tmptrack->mogadm("fsck", "stop"), "stop fsck");
 100     ok($tmptrack->mogadm("fsck", "clearlog"), "clear fsck log");
 101     ok($tmptrack->mogadm("fsck", "reset"), "reset fsck");
 102     ok($tmptrack->mogadm("fsck", "start"), "started fsck");
 103 }
 104
 105 sub unblock_fsck_queue {
 106     my ($sto, $expect) = @_;
 107     my $now = $sto->unix_timestamp;
 108     my $upd = sub { $sto->dbh->do("UPDATE file_to_queue SET nexttry = $now") };
 109     is($sto->retry_on_deadlock($upd), $expect, "unblocked fsck queue");
 110 }
 111
 112 wait_for_monitor($be);
 113
 114 my ($req, $rv, %opts, @paths, @fsck_log, $info);
 115 my $ua = LWP::UserAgent->new;
 116 my $key = "testkey";
 117 my $dbh = $sto->dbh;
 118
 119 use Data::Dumper;
 120
 121 # upload a file and wait for replica to appear
 122 {
 123     my $fh = $mogc->new_file($key, "1copy");
 124     print $fh "hello\n";
 125     ok(close($fh), "closed file");
 126 }
 127
 128 # first obvious fucked-up case:  no devids even presumed to exist.
 129 {
 130     $info = $mogc->file_info($key);
 131     is($info->{devcount}, 1, "ensure devcount is correct at start");
 132
 133     # ensure repl queue is empty before destroying file_on
 134     wait_for_empty_queue("file_to_replicate", $dbh);
 135
 136     my @devids = $sto->fid_devids($info->{fid});
 137     is(scalar(@devids), 1, "devids retrieved");
 138     is($sto->remove_fidid_from_devid($info->{fid}, $devids[0]), 1,
 139        "delete $key from file_on table");
 140
 141     full_fsck($tmptrack, $dbh);
 142     do {
 143         @fsck_log = $sto->fsck_log_rows;
 144     } while (scalar(@fsck_log) < 3 && sleep(0.1));
 145
 146     wait_for_empty_queue("file_to_queue", $dbh);
 147     @fsck_log = $sto->fsck_log_rows;
 148
 149     my $nopa = $fsck_log[0];
 150     is($nopa->{evcode}, "NOPA", "evcode for no paths logged");
 151
 152     # entering "desperate" mode
 153     my $srch = $fsck_log[1];
 154     is($srch->{evcode}, "SRCH", "evcode for start search logged");
 155
 156     # wow, we actually found it!
 157     my $fond = $fsck_log[2];
 158     is($fond->{evcode}, "FOND", "evcode for start search logged");
 159
 160     $info = $mogc->file_info($key);
 161     is($info->{devcount}, 1, "ensure devcount is correct at fsck end");
 162     @paths = $mogc->get_paths($key);
 163     is(scalar(@paths), 1, "get_paths returns correctly at fsck end");
 164 }
 165
 166 # update class to require 2copies and have fsck fix it
 167 {
 168     @paths = $mogc->get_paths($key);
 169     is(scalar(@paths), 1, "only one path exists before fsck");
 170
 171     # _NOT_ using "updateclass" command since that enqueues for replication
 172     my $fid = MogileFS::FID->new($info->{fid});
 173     my $classid_2copies = $sto->get_classid_by_name($fid->dmid, "2copies");
 174     is($fid->update_class(classid => $classid_2copies), 1, "classid updated");
 175
 176     full_fsck($tmptrack, $dbh);
 177
 178     do {
 179         @paths = $mogc->get_paths($key);
 180     } while (scalar(@paths) == 1 and sleep(0.1));
 181     is(scalar(@paths), 2, "replicated from fsck");
 182
 183     $info = $mogc->file_info($key);
 184     is($info->{devcount}, 2, "ensure devcount is updated by replicate");
 185
 186     do {
 187         @fsck_log = $sto->fsck_log_rows;
 188     } while (scalar(@fsck_log) == 0 and sleep(0.1));
 189
 190     my $povi = $fsck_log[0];
 191     is($povi->{evcode}, "POVI", "policy violation logged by fsck");
 192
 193     my $repl = $fsck_log[1];
 194     is($repl->{evcode}, "REPL", "replication request logged by fsck");
 195 }
 196
 197 # wrong devcount in file column, but otherwise everything is OK
 198 {
 199     foreach my $wrong_devcount (13, 0, 1) {
 200         my $upd = sub {
 201             $dbh->do("UPDATE file SET devcount = ? WHERE fid = ?",
 202                      undef, $wrong_devcount, $info->{fid});
 203         };
 204         is($sto->retry_on_deadlock($upd), 1, "set improper devcount");
 205
 206         $info = $mogc->file_info($key);
 207         is($info->{devcount}, $wrong_devcount, "devcount is set to $wrong_devcount");
 208
 209         full_fsck($tmptrack, $dbh);
 210
 211         do {
 212             $info = $mogc->file_info($key);
 213         } while ($info->{devcount} == $wrong_devcount && sleep(0.1));
 214         is($info->{devcount}, 2, "devcount is corrected by fsck");
 215
 216         wait_for_empty_queue("file_to_queue", $dbh);
 217         @fsck_log = $sto->fsck_log_rows;
 218         is($fsck_log[0]->{evcode}, "BCNT", "bad count logged");
 219     }
 220 }
 221
 222 # nuke a file from disk but keep the file_on row
 223 {
 224     @paths = $mogc->get_paths($key);
 225     is(scalar(@paths), 2, "two paths returned from get_paths");
 226     $req = HTTP::Request->new(DELETE => $paths[0]);
 227     $rv = $ua->request($req);
 228     ok($rv->is_success, "DELETE successful");
 229
 230     full_fsck($tmptrack, $dbh);
 231     do {
 232         @fsck_log = $sto->fsck_log_rows;
 233     } while (scalar(@fsck_log) < 2 && sleep(0.1));
 234
 235     my $miss = $fsck_log[0];
 236     is($miss->{evcode}, "MISS", "missing file logged by fsck");
 237
 238     my $repl = $fsck_log[1];
 239     is($repl->{evcode}, "REPL", "replication request logged by fsck");
 240
 241     wait_for_empty_queue("file_to_replicate", $dbh);
 242
 243     @paths = $mogc->get_paths($key);
 244     is(scalar(@paths), 2, "two paths returned from get_paths");
 245     foreach my $path (@paths) {
 246         $rv = $ua->get($path);
 247         is($rv->content, "hello\n", "GET successful on restored path");
 248     }
 249 }
 250
 251 # change the length of a file from disk and have fsck correct it
 252 {
 253     @paths = $mogc->get_paths($key);
 254     is(scalar(@paths), 2, "two paths returned from get_paths");
 255     $req = HTTP::Request->new(PUT => $paths[0]);
 256     $req->content("hello\r\n");
 257     $rv = $ua->request($req);
 258     ok($rv->is_success, "PUT successful");
 259
 260     full_fsck($tmptrack, $dbh);
 261     do {
 262         @fsck_log = $sto->fsck_log_rows;
 263     } while (scalar(@fsck_log) < 2 && sleep(0.1));
 264
 265     my $blen = $fsck_log[0];
 266     is($blen->{evcode}, "BLEN", "missing file logged by fsck");
 267
 268     my $repl = $fsck_log[1];
 269     is($repl->{evcode}, "REPL", "replication request logged by fsck");
 270
 271     wait_for_empty_queue("file_to_replicate", $dbh);
 272
 273     @paths = $mogc->get_paths($key);
 274     is(scalar(@paths), 2, "two paths returned from get_paths");
 275     foreach my $path (@paths) {
 276         $rv = $ua->get($path);
 277         is($rv->content, "hello\n", "GET successful on restored path");
 278     }
 279 }
 280
 281 # nuke a file completely and irreparably
 282 {
 283     @paths = $mogc->get_paths($key);
 284     is(scalar(@paths), 2, "two paths returned from get_paths");
 285     foreach my $path (@paths) {
 286         $req = HTTP::Request->new(DELETE => $path);
 287         $rv = $ua->request($req);
 288         ok($rv->is_success, "DELETE successful");
 289     }
 290
 291     full_fsck($tmptrack, $dbh);
 292     do {
 293         @fsck_log = $sto->fsck_log_rows;
 294     } while (scalar(@fsck_log) < 4 && sleep(0.1));
 295
 296     is($fsck_log[0]->{evcode}, "MISS", "missing file logged for first path");
 297     is($fsck_log[1]->{evcode}, "MISS", "missing file logged for second path");
 298     is($fsck_log[2]->{evcode}, "SRCH", "desperate search attempt logged");
 299     is($fsck_log[3]->{evcode}, "GONE", "inability to fix FID logged");
 300
 301     wait_for_empty_queue("file_to_queue", $dbh);
 302     $info = $mogc->file_info($key);
 303
 304     # XXX devcount probably needs to be updated on GONE
 305     # is($info->{devcount}, 2, "devcount updated to zero");
 306     @paths = $mogc->get_paths($key);
 307     is(scalar(@paths), 0, "get_paths returns nothing");
 308 }
 309
 310 # upload a file and wait for replica to appear
 311 {
 312     my $fh = $mogc->new_file($key, "2copies");
 313     print $fh "hello\n";
 314     ok(close($fh), "closed file");
 315
 316     do {
 317         $info = $mogc->file_info($key);
 318     } while ($info->{devcount} < 2);
 319     is($info->{devcount}, 2, "ensure devcount is correct at start");
 320 }
 321
 322 # stall fsck with a non-responsive host
 323 {
 324     is(kill("STOP", $ms1->pid), 1, "send SIGSTOP to mogstored1");
 325     wait_for_monitor($be);
 326
 327     my $delay = 10;
 328     ok($tmptrack->mogadm("fsck", "start"), "started fsck, sleeping ${delay}s");
 329     sleep $delay;
 330     is($sto->file_queue_length(MogileFS::Config::FSCK_QUEUE), 1, "fsck queue still blocked");
 331 }
 332
 333 # resume fsck when host is responsive again
 334 {
 335     is(kill("CONT", $ms1->pid), 1, "send SIGCONT to mogstored1");
 336     wait_for_monitor($be);
 337
 338     # force fsck to wakeup and do work again
 339     unblock_fsck_queue($sto, 1);
 340
 341     ok($admin->syswrite("!to fsck :wake_up\n"), "force fsck to wake up");
 342     ok($admin->getline, "got wakeup response 1");
 343     ok($admin->getline, "got wakeup response 2");
 344
 345     foreach my $i (1..30) {
 346         last if $sto->file_queue_length(MogileFS::Config::FSCK_QUEUE) == 0;
 347
 348         sleep 1;
 349     }
 350
 351     is($sto->file_queue_length(MogileFS::Config::FSCK_QUEUE), 0, "fsck queue emptied");
 352 }
 353
 354 # upload a file and wait for replica to appear
 355 {
 356     my $fh = $mogc->new_file($key, "2copies");
 357     print $fh "hello\n";
 358     ok(close($fh), "closed file");
 359
 360     do {
 361         $info = $mogc->file_info($key);
 362     } while ($info->{devcount} < 2);
 363     is($info->{devcount}, 2, "ensure devcount is correct at start");
 364 }
 365
 366 # stall fsck with a non-responsive host
 367 # resume fsck when host is responsive again
 368 {
 369     is(kill("STOP", $ms1->pid), 1, "send SIGSTOP to mogstored1 to stall");
 370     wait_for_monitor($be);
 371
 372     my $delay = 10;
 373     ok($tmptrack->mogadm("fsck", "start"), "started fsck, sleeping ${delay}s");
 374     sleep $delay;
 375     is($sto->file_queue_length(MogileFS::Config::FSCK_QUEUE), 1, "fsck queue still blocked");
 376
 377     is(kill("CONT", $ms1->pid), 1, "send SIGCONT to mogstored1 to resume");
 378     wait_for_monitor($be);
 379
 380     # force fsck to wakeup and do work again
 381     unblock_fsck_queue($sto, 1);
 382     ok($admin->syswrite("!to fsck :wake_up\n"), "force fsck to wake up");
 383     ok($admin->getline, "got wakeup response 1");
 384     ok($admin->getline, "got wakeup response 2");
 385
 386     foreach my $i (1..30) {
 387         last if $sto->file_queue_length(MogileFS::Config::FSCK_QUEUE) == 0;
 388
 389         sleep 1;
 390     }
 391
 392     is($sto->file_queue_length(MogileFS::Config::FSCK_QUEUE), 0, "fsck queue emptied");
 393 }
 394
 395 # cleanup over-replicated file
 396 {
 397     $info = $mogc->file_info($key);
 398     is($info->{devcount}, 2, "ensure devcount is correct at start");
 399
 400     # _NOT_ using "updateclass" command since that enqueues for replication
 401     my $fid = MogileFS::FID->new($info->{fid});
 402     my $classid_1copy = $sto->get_classid_by_name($fid->dmid, "1copy");
 403     is($fid->update_class(classid => $classid_1copy), 1, "classid updated");
 404
 405     full_fsck($tmptrack, $dbh);
 406
 407     sleep(1) while $mogc->file_info($key)->{devcount} == 2;
 408     is($mogc->file_info($key)->{devcount}, 1, "too-happy file cleaned up");
 409
 410     @fsck_log = $sto->fsck_log_rows;
 411     is($fsck_log[0]->{evcode}, "POVI", "policy violation logged");
 412
 413     # replicator is requested to delete too-happy file
 414     is($fsck_log[1]->{evcode}, "REPL", "replication request logged");
 415 }
 416
 417 # kill a device and replace it with another, without help from reaper
 418 # this test may become impossible if monitor + reaper are merged...
 419 {
 420     ok($mogc->update_class($key, "2copies"), "request 2 replicas again");
 421     do {
 422         $info = $mogc->file_info($key);
 423     } while ($info->{devcount} < 2);
 424     is($info->{devcount}, 2, "ensure devcount is correct at start");
 425     wait_for_empty_queue("file_to_replicate", $dbh);
 426
 427     $admin->syswrite("!jobs\n");
 428     my $reaper_pid;
 429
 430     while (my $line = $admin->getline) {
 431         last if $line =~ /^\.\r?\n/;
 432
 433         if ($line =~ /^reaper pids (\d+)\r?\n/) {
 434             $reaper_pid = $1;
 435         }
 436     }
 437     ok($reaper_pid, "got pid of reaper");
 438
 439     # reaper is watchdog is 240s, and it wakes up in 5s intervals right now
 440     # so we should be safe from watchdog for now...
 441     ok(kill("STOP", $reaper_pid), "stopped reaper from running");
 442
 443     ok($tmptrack->mogadm("device", "mark", "hostB", 2, "dead"), "mark dev2 as dead");
 444     ok($tmptrack->mogadm("device", "add", "hostB", 3), "created dev3 on hostB");
 445     wait_for_monitor($be);
 446
 447     full_fsck($tmptrack, $dbh);
 448
 449     sleep 1 while MogileFS::Config->server_setting("fsck_host");
 450
 451     foreach my $i (1..30) {
 452         last if $sto->file_queue_length(MogileFS::Config::FSCK_QUEUE) == 0;
 453         sleep 1;
 454     }
 455     is($sto->file_queue_length(MogileFS::Config::FSCK_QUEUE), 0, "fsck queue empty");
 456
 457     # fsck should've corrected what reaper missed
 458     @fsck_log = $sto->fsck_log_rows;
 459     is(scalar(@fsck_log), 1, "fsck log populated");
 460     is($fsck_log[0]->{evcode}, "REPL", "replication enqueued");
 461
 462     ok(kill("CONT", $reaper_pid), "resumed reaper");
 463 }
 464
 465 {
 466     foreach my $i (1..10) {
 467         my $fh = $mogc->new_file("k$i", "1copy");
 468         print $fh "$i\n";
 469         ok(close($fh), "closed file ($i)");
 470     }
 471     $info = $mogc->file_info("k10");
 472
 473     ok($tmptrack->mogadm("settings", "set", "queue_rate_for_fsck", 1), "set queue_rate_for_fsck to 1");
 474     ok($tmptrack->mogadm("settings", "set", "queue_size_for_fsck", 1), "set queue_size_for_fsck to 1");
 475     wait_for_monitor($be);
 476
 477     ok($tmptrack->mogadm("fsck", "start"), "start fsck with slow queue rate");
 478
 479     ok(MogileFS::Config->server_setting("fsck_host"), "fsck_host set");
 480     is(MogileFS::Config->server_setting("fsck_fid_at_end"), $info->{fid}, "fsck_fid_at_end matches");
 481
 482     my $highest = undef;
 483     foreach my $i (1..100) {
 484         $highest = MogileFS::Config->server_setting("fsck_highest_fid_checked");
 485         last if defined $highest;
 486         sleep 0.1;
 487     }
 488     ok(defined($highest), "fsck_highest_fid_checked is set");
 489     like($highest, qr/\A\d+\z/, "fsck_highest_fid_checked is a digit");
 490
 491     # wait for something to get fscked
 492     foreach my $i (1..100) {
 493         last if MogileFS::Config->server_setting("fsck_highest_fid_checked") != $highest;
 494         sleep 0.1;
 495     }
 496
 497     my $old_highest = $highest;
 498     $highest = MogileFS::Config->server_setting("fsck_highest_fid_checked");
 499     isnt($highest, $old_highest, "moved to next FID");
 500
 501     ok($tmptrack->mogadm("fsck", "stop"), "stop fsck");
 502     ok(! MogileFS::Config->server_setting("fsck_host"), "fsck_host unset");
 503     is(MogileFS::Config->server_setting("fsck_fid_at_end"), $info->{fid}, "fsck_fid_at_end matches");
 504
 505     # resume paused fsck
 506     ok($tmptrack->mogadm("fsck", "start"), "restart fsck");
 507     $highest = MogileFS::Config->server_setting("fsck_highest_fid_checked");
 508     cmp_ok($highest, '>=', $old_highest, "fsck resumed without resetting fsck_highest_fid_checked");
 509
 510     # wait for something to get fscked
 511     foreach my $i (1..200) {
 512         last if MogileFS::Config->server_setting("fsck_highest_fid_checked") != $highest;
 513         sleep 0.1;
 514     }
 515
 516     $highest = MogileFS::Config->server_setting("fsck_highest_fid_checked");
 517     cmp_ok($highest, '>', $old_highest, "fsck continued to higher FID");
 518 }
 519
 520 done_testing();