Changeset 1547
- Timestamp:
- 04/22/08 02:22:00 (3 weeks ago)
- Files:
-
- honeyclient/trunk/etc/honeyclient.xml (modified) (1 diff)
- honeyclient/trunk/lib/HoneyClient/Manager.pm (modified) (7 diffs)
- honeyclient/trunk/lib/HoneyClient/Manager/VM.pm (modified) (13 diffs)
- honeyclient/trunk/lib/HoneyClient/Manager/VM/Clone.pm (modified) (38 diffs)
Legend:
- Unmodified
- Added
- Removed
- Modified
- Copied
- Moved
honeyclient/trunk/etc/honeyclient.xml
r1538 r1547 178 178 </Crawler> 179 179 <Manager> 180 <num_simultaneous_clones description="Upon startup, the Manager will attempt to spawn the specified number of cloned VMs simultaneously. To figure out an optimal value, take the amount of RAM allocated for your master VM (e.g., 256MB) and multiply that amount by this specified number (e.g., 4 simultaneous VMs x 256MB = 1GB). You want to make sure that the total RAM requirements do not exceed the amount of RAM the host system can provision. Allow the host system at least 512MB of RAM for normal operations." default="1"> 181 1 182 </num_simultaneous_clones> 180 183 <fingerprint_dump description="When the Manager encounters a suspicious VM, it will attempt to append a complete copy of the fingerprint information to this file, if specified."> 181 184 fingerprint.dump honeyclient/trunk/lib/HoneyClient/Manager.pm
r1499 r1547 287 287 our $LOG = get_logger(); 288 288 289 # The global work queue. Each entry represents 290 # work destined for a child thread worker. 291 our $WORK_QUEUE : shared = undef; 292 293 # The global wait queue. Each entry represents 294 # a thread ID waiting for more work. 295 our $WAIT_QUEUE : shared = undef; 296 289 297 ####################################################################### 290 298 # Daemon Initialization / Destruction # … … 418 426 }; 419 427 428 # Verify all sub threads are finished, prior to shutting down. 429 my $thread; 430 foreach $thread (threads->list()) { 431 # Don't kill/detach the main thread or ourselves. 432 if ($thread->tid() && !$thread->equal(threads->self())) { 433 # Kill the child thread, if it's running. 434 if ($thread->is_running()) { 435 # Send empty work, if need be. 436 my $work = {}; 437 $WORK_QUEUE->enqueue(nfreeze($work)); 438 439 $LOG->info("Shutting down Thread ID (" . $thread->tid() . ")."); 440 $thread->kill('USR1'); 441 442 # Join the child thread. 443 if (!$thread->is_detached()) { 444 $LOG->debug("Joining Thread ID (" . $thread->tid() . ")."); 445 $thread->join(); 446 } 447 } 448 } 449 } 450 420 451 # XXX: There is an issue where if we try to quit but are in the 421 452 # process of asynchronously archiving a VM, then the async archive … … 425 456 kill("KILL", -$$); 426 457 } 458 459 # Helper function designed to "pop" a (key, value) pair off a given hashtable. 460 # When given a hashtable reference, this function will extract a valid (key, value) 461 # pair from the hashtable and delete the (key, value) pair from the 462 # hashtable. The (key, value) pair with the highest score is returned. 463 # 464 # Inputs: hashref 465 # Outputs: valid (key, val) hashref or undef if the hash is empty 466 sub _pop { 467 468 # Get supplied hash reference. 469 my $hash = shift; 470 471 # Get the highest score. 472 my @array = sort {$$hash{$b} <=> $$hash{$a}} keys %{$hash}; 473 my $topkey = $array[0]; 474 475 if (defined($topkey)) { 476 # Delete the key from the hashtable. 477 # Return the (key, val) pair found. 478 return { $topkey => delete($hash->{$topkey}) }; 479 } else { 480 return undef; 481 } 482 } 483 484 # Helper function designed to take in specified work 485 # and split up that work evenly amongst the specified 486 # number of clones by creating individual "buckets" 487 # for each clone, adding non-empty buckets to the 488 # work queue. 489 # 490 # Inputs: work_queue, wait_queue, work, num_simultaneous_clones 491 # Outputs: None. 492 sub _divide_work { 493 494 # Extract arguments. 495 my (%args) = @_; 496 497 # Initalize buckets - 1 bucket per client. 498 my $buckets = [ ]; 499 for (my $counter = 0; $counter < $args{'num_simultaneous_clones'}; $counter++) { 500 $buckets->[$counter] = { }; 501 } 502 503 # Divide up the work evenly across each bucket. 504 while (scalar(%{$args{'work'}})) { 505 for (my $counter = 0; $counter < $args{'num_simultaneous_clones'}; $counter++) { 506 my $item = _pop($args{'work'}); 507 if (defined($item)) { 508 $buckets->[$counter] = { %{$buckets->[$counter]}, %{$item} }; 509 } else { 510 # We have no more work to place into any bucket, 511 # so exit the loop. 512 last; 513 } 514 } 515 } 516 517 # Place the contents of each bucket onto the work queue, 518 # but ignore empty buckets. 519 my $tid = undef; 520 for (my $counter = 0; $counter < $args{'num_simultaneous_clones'}; $counter++) { 521 if (scalar %{$buckets->[$counter]}) { 522 523 # For each bucket inserted into the work queue, delete a corresponding 524 # signal from the wait queue -- if there is a signal on the wait queue. 525 if (defined($tid = $args{'wait_queue'}->dequeue_nb)) { 526 527 # Sanity check: Make sure the thread is still alive. 528 if (!defined(threads->object($tid))) { 529 $LOG->error("Thread ID (" . $tid . "): Unexpectedly terminated."); 530 Carp::croak "Thread ID (" . $tid . "): Unexpectedly terminated."; 531 } 532 533 } 534 535 # TODO: Delete this, eventually. 536 print "\nBucket #" . $counter . ":\n" . Dumper($buckets->[$counter]) . "\n\n"; 537 $args{'work_queue'}->enqueue(nfreeze($buckets->[$counter])); 538 } 539 } 540 } 541 542 543 # Signal handler to help give user immediate feedback during 544 # shutdown process. 545 sub _shutdown { 546 my $LOG = get_logger(); 547 $LOG->warn("Received termination signal. Shutting down (please wait)."); 548 exit; 549 }; 550 $SIG{HUP} = \&_shutdown; 551 $SIG{INT} = \&_shutdown; 552 $SIG{QUIT} = \&_shutdown; 553 $SIG{ABRT} = \&_shutdown; 554 $SIG{TERM} = \&_shutdown; 427 555 428 556 ####################################################################### … … 496 624 } 497 625 498 # Create a new cloned VM. 499 $vm = HoneyClient::Manager::VM::Clone->new(%args); 626 # Create a new work queue. 627 $WORK_QUEUE = new Thread::Queue; 628 629 # Create a new wait queue. 630 $WAIT_QUEUE = new Thread::Queue; 631 632 # Create the thread pool. 633 my @THREAD_POOL; 634 635 # Create the cloned VMs. 636 for (my $counter = 0; $counter < getVar(name => "num_simultaneous_clones"); $counter++) { 637 my $thread = threads->create(\&_worker, \%args); 638 if (!defined($thread)) { 639 $LOG->error("Unable to create worker thread! Shutting down."); 640 Carp::croak "Unable to create worker thread! Shutting down."; 641 } 642 # Push thread onto thread pool. 643 push(@THREAD_POOL, $thread); 644 } 500 645 501 646 # If supported, get a URL list from the database. 502 647 my $remoteLinksExist = 0; 503 648 my $queue_url_list = {}; 504 while (defined($vm->database_id)) { 649 my $tid = undef; 650 while (getVar(name => "enable", 651 namespace => "HoneyClient::Manager::Database")) { 505 652 $LOG->info("Waiting for new URLs from database."); 506 $queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), $vm->database_id); 653 # TODO: Fix this. 654 #$queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), $vm->database_id); 655 $queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), 1145); 507 656 $remoteLinksExist = scalar(%{$queue_url_list}); 508 657 while (!$localLinksExist && !$remoteLinksExist) { … … 512 661 # XXX: Trap/ignore all errors and simply retry. 513 662 eval { 514 $queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), $vm->database_id); 663 # TODO: Fix this. 664 #$queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), $vm->database_id); 665 $queue_url_list = HoneyClient::Manager::Database::get_queue_urls(getVar(name => "num_urls_to_process"), 1145); 515 666 $remoteLinksExist = scalar(%{$queue_url_list}); 516 667 }; … … 522 673 } 523 674 524 # Drive the VM, using the work found. 525 $vm = $vm->drive(work => $args{'work'}); 675 # Drive the VMs, using the work found. 676 $LOG->info("Received new work and updating queue."); 677 _divide_work(work_queue => $WORK_QUEUE, 678 wait_queue => $WAIT_QUEUE, 679 work => $args{'work'}, 680 num_simultaneous_clones => getVar(name => "num_simultaneous_clones")); 681 682 # Wait until the VMs need more work. 683 while (!$WAIT_QUEUE->pending) { 684 # Poll the wait queue every 2 seconds. 685 # This time delay should be short. 686 threads->yield(); 687 sleep(2); 688 689 # Make sure all worker threads are still alive. 690 for (my $counter = 0; $counter < getVar(name => "num_simultaneous_clones"); $counter++) { 691 my $thread = $THREAD_POOL[$counter]; 692 if (!$thread->is_running()) { 693 $LOG->error("Thread ID (" . $thread->tid() . "): Unexpectedly terminated."); 694 Carp::croak "Thread ID (" . $thread->tid() . "): Unexpectedly terminated."; 695 } 696 } 697 } 698 $LOG->info("Got a signal that a thread needs more work."); 699 526 700 # Once finished, empty the work queue. 527 701 $args{'work'} = {}; … … 535 709 # that was provided from the command line and then shut down. 536 710 if (scalar(%{$args{'work'}})) { 537 $vm = $vm->drive(work => $args{'work'}); 711 712 # Drive the VMs, using the work found. 713 $LOG->info("Received new work and updating queue."); 714 _divide_work(work_queue => $WORK_QUEUE, 715 wait_queue => $WAIT_QUEUE, 716 work => $args{'work'}, 717 num_simultaneous_clones => getVar(name => "num_simultaneous_clones")); 718 719 # Wait until all VMs are finished. 720 # We wait for each worker to signal that they are waiting for more work, before shutting down 721 # the application. 722 for (my $i = 0; $i < getVar(name => "num_simultaneous_clones"); $i++) { 723 my $tid = undef; 724 # This is a little hackish, since calling Thread::Queue->dequeue 725 # doesn't properly handle signals. 726 while (!defined($tid = $WAIT_QUEUE->dequeue_nb)) { 727 # Poll the wait queue every 2 seconds. 728 # This time delay should be short. 729 threads->yield(); 730 sleep(2); 731 732 # Make sure all worker threads are still alive. 733 for (my $counter = 0; $counter < getVar(name => "num_simultaneous_clones"); $counter++) { 734 my $thread = $THREAD_POOL[$counter]; 735 if (!$thread->is_running()) { 736 $LOG->error("Thread ID (" . $thread->tid() . "): Unexpectedly terminated."); 737 Carp::croak "Thread ID (" . $thread->tid() . "): Unexpectedly terminated."; 738 } 739 } 740 } 741 } 538 742 # Once finished, empty the work queue. 539 743 $args{'work'} = {}; 540 744 } 541 745 $LOG->info("All URLs exhausted. Shutting down Manager."); 746 } 747 748 # TODO: Comment this. 749 # Note: We can gracefully stop each worker, by sending an empty hashtable of work, 750 # or by signalling the thread. 751 sub _worker { 752 753 # Make sure the thread can only kill itself and not the entire application. 754 threads->set_thread_exit_only(1); 755 756 # Register interrupt/kill signal handlers. 757 # These handlers are designed to kill this thread upon overall module 758 # destruction. These handlers should never be used for normal program 759 # operations, since they will NOT release any locks/semaphores properly. 760 local $SIG{USR1} = sub { 761 my $LOG = get_logger(); 762 $LOG->warn("Thread ID (" . threads->tid() . "): Received SIGUSR1. Shutting down worker."); 763 threads->exit(); 764 }; 765 766 local $SIG{INT} = sub { 767 my $LOG = get_logger(); 768 $LOG->warn("Thread ID (" . threads->tid() . "): Received SIGINT. Shutting down worker."); 769 threads->exit(); 770 }; 771 772 # Extract arguments. 773 my $args = shift; 774 775 $LOG->info("Thread ID (" . threads->tid() . "): Starting worker."); 776 777 # Yield processing to parent thread. 778 threads->yield(); 779 780 eval { 781 # Create a new cloned VM. 782 my $vm = HoneyClient::Manager::VM::Clone->new(%{$args}); 783 784 # Variable to hold our work. 785 my $work = undef; 786 my $data = undef; 787 788 # If there's no work on the queue, signal that we need more work. 789 if (!$WORK_QUEUE->pending) { 790 $LOG->info("Thread ID (" . threads->tid() . "): Signaling for more work."); 791 # Signal that we're ready for more work. 792 $WAIT_QUEUE->enqueue(threads->tid()); 793 } 794 795 # This is a little hackish, since calling Thread::Queue->dequeue 796 # doesn't properly handle signals. 797 $LOG->info("Thread ID (" . threads->tid() . "): Waiting for more work."); 798 while (!defined($data = $WORK_QUEUE->dequeue_nb)) { 799 # Poll the wait queue every 2 seconds. 800 # This time delay should be short. 801 threads->yield(); 802 sleep(2); 803 } 804 $work = thaw($data); 805 806 while (scalar(%{$work})) { 807 $vm = $vm->drive(work => $work); 808 809 # If there's no work on the queue, signal that we need more work. 810 if (!$WORK_QUEUE->pending) { 811 $LOG->info("Thread ID (" . threads->tid() . "): Signaling for more work."); 812 # Signal that we're ready for more work. 813 $WAIT_QUEUE->enqueue(threads->tid()); 814 } 815 # This is a little hackish, since calling Thread::Queue->dequeue 816 # doesn't properly handle signals. 817 $LOG->info("Thread ID (" . threads->tid() . "): Waiting for more work."); 818 while (!defined($data = $WORK_QUEUE->dequeue_nb)) { 819 # Poll the wait queue every 2 seconds. 820 # This time delay should be short. 821 threads->yield(); 822 sleep(2); 823 } 824 $work = thaw($data); 825 } 826 }; 827 # Report when a fault occurs. 828 if ($@) { 829 $LOG->warn("Thread ID (" . threads->tid() . "): Encountered an error. Shutting down worker. " . $@); 830 } else { 831 $LOG->info("Thread ID (" . threads->tid() . "): Received empty work. Shutting down worker."); 832 } 833 834 # Signal to the parent that we're shutting down. 835 if (!threads->is_detached()) { 836 threads->detach(); 837 } 838 $WAIT_QUEUE->enqueue(threads->tid()); 839 840 # Shut thread down. 841 threads->exit(); 542 842 } 543 843 honeyclient/trunk/lib/HoneyClient/Manager/VM.pm
r1518 r1547 613 613 # used to guarantee only one operation per VM is performed 614 614 # at any given time. 615 our %vmSemaphoreHash ;615 our %vmSemaphoreHash : shared; 616 616 617 617 # Global semaphore, designed to limit exclusive access … … 2304 2304 $vmSemaphore->up(); 2305 2305 $maxThreadSemaphore->up(); 2306 return;2306 threads->exit(); 2307 2307 }; 2308 2308 … … 2363 2363 2364 2364 $maxThreadSemaphore->up(); 2365 return;2365 threads->exit(); 2366 2366 }; 2367 2367 … … 4101 4101 # $vmSemaphore->up(); 4102 4102 # $maxThreadSemaphore->up(); 4103 # return;4103 # threads->exit(); 4104 4104 # }; 4105 4105 # … … 4170 4170 # 4171 4171 # $maxThreadSemaphore->up(); 4172 # return;4172 # threads->exit(); 4173 4173 # }; 4174 4174 … … 4378 4378 4379 4379 # Perform the snapshot operations... 4380 # Since this usually takes awhile, we perform the remaining operations in a child thread. 4380 if ($powerState != VM_EXECUTION_STATE_SUSPENDED && 4381 $powerState != VM_EXECUTION_STATE_OFF) { 4382 4383 # Okay, the VM is alive; so suspend it... 4384 suspendVM($class, %args); 4385 } 4386 4387 # Now, temporarily unregister the VM, in order to ensure 4388 # it doesn't get used while we snapshot it. 4389 unregisterVM($class, %args); 4390 4391 4392 # Since this may take awhile, we perform the remaining operations in a child thread. 4381 4393 my $thread = async { 4382 4394 … … 4399 4411 $vmSemaphore->up(); 4400 4412 $maxThreadSemaphore->up(); 4401 return;4413 threads->exit(); 4402 4414 }; 4403 4415 … … 4407 4419 # Yes, this is annoying and ugly. 4408 4420 eval { 4409 4410 if ($powerState != VM_EXECUTION_STATE_SUSPENDED &&4411 $powerState != VM_EXECUTION_STATE_OFF) {4412 4413 # Okay, the VM is alive; so suspend it...4414 _callback($class, "suspendVM", %args);4415 }4416 4417 # Now, temporarily unregister the VM, in order to ensure4418 # it doesn't get used while we snapshot it.4419 _callback($class, "unregisterVM", %args);4420 4421 4421 4422 # Lock the VM. … … 4432 4433 chdir $pwd; 4433 4434 4434 # Unlock chdirSemaphore.4435 $chdirSemaphore->up();4436 4435 4437 4436 if (system(getVar(name => "bin_tar"), '-C', $parentDir, '-zcpf', $args{'snapshot_file'}, @fileList) != 0) { 4438 4437 # Unlock VM, if fail. 4438 $chdirSemaphore->up(); 4439 4439 $vmSemaphore->up(); 4440 4440 $LOG->warn("Could not snapshot VM to ($args{'snapshot_file'}). " . … … 4446 4446 'err'); 4447 4447 } 4448 4449 # Unlock chdirSemaphore. 4450 $chdirSemaphore->up(); 4448 4451 4449 4452 # Unlock the VM. … … 4465 4468 } 4466 4469 $maxThreadSemaphore->up(); 4467 return;4470 threads->exit(); 4468 4471 }; 4469 4472 … … 4707 4710 $LOG->warn("Asynchronous revert of ($vmDir) interrupted!"); 4708 4711 $maxThreadSemaphore->up(); 4709 return;4712 threads->exit(); 4710 4713 }; 4711 4714 … … 4764 4767 } 4765 4768 $maxThreadSemaphore->up(); 4766 return;4769 threads->exit(); 4767 4770 }; 4768 4771 honeyclient/trunk/lib/HoneyClient/Manager/VM/Clone.pm
r1499 r1547 303 303 use threads::shared; 304 304 305 # Make sure Thread::Semaphore loads. 306 BEGIN { use_ok('Thread::Semaphore') or diag("Can't load Thread::Semaphore package. Check to make sure the package library is correctly listed within the path."); } 307 require_ok('Thread::Semaphore'); 308 use Thread::Semaphore; 309 305 310 # Make sure File::Basename loads. 306 311 BEGIN { use_ok('File::Basename', qw(dirname basename)) or diag("Can't load File::Basename package. Check to make sure the package library is correctly listed within the path."); } … … 345 350 use threads; 346 351 use threads::shared; 352 use Thread::Semaphore; 347 353 348 354 # Include Global Configuration Processing Library … … 386 392 # Clone objects that have been created. 387 393 our $OBJECT_COUNT : shared = -1; 394 395 # Global semaphore, designed to guarantee only one 396 # thread may set/access the $OBJECT_COUNT variable 397 # at any given time. 398 our $OBJECT_COUNT_SEMAPHORE = Thread::Semaphore->new(1); 388 399 389 400 # Include Database Libraries … … 559 570 fault_handler => sub { die "ERROR"; }); 560 571 561 $LOG->info(" Suspending clone VM (" . $self->{'config'} . ").");572 $LOG->info("Thread ID (" . threads->tid() . "): Suspending clone VM (" . $self->{'config'} . ")."); 562 573 my $som = undef; 563 574 eval { … … 568 579 # a CTRL-C or other forced termination. 569 580 unless(defined($som)) { 581 # XXX: There may be an issue with multiple threads attempting 582 # to all run DESTROY simultaneously. Worst case scenario should 583 # be a warning indicating that the VM daemon bound address is 584 # already in use. 585 570 586 # Make sure the VM daemon was properly destroyed. 571 587 HoneyClient::Manager::VM->destroy(); … … 582 598 583 599 if (!defined($som)) { 584 $LOG->error(" Unable to suspend VM (" . $self->{'config'} . ").");600 $LOG->error("Thread ID (" . threads->tid() . "): Unable to suspend VM (" . $self->{'config'} . ")."); 585 601 $self->_changeStatus(status => "error"); 586 602 } else { … … 596 612 # Upon termination, destroy the global instance of the VM manager. 597 613 if ($OBJECT_COUNT == 0) { 598 $LOG->debug(" Destroying VM daemon.");614 $LOG->debug("Thread ID (" . threads->tid() . "): Destroying VM daemon."); 599 615 HoneyClient::Manager::VM->destroy(); 600 616 } … … 622 638 623 639 if ($errMsg !~ /Unable to flush entries in chain/) { 624 $LOG->warn(" Error occurred during processing. " . $errMsg);640 $LOG->warn("Thread ID (" . threads->tid() . "): Error occurred during processing. " . $errMsg); 625 641 Carp::carp __PACKAGE__ . "->_handleFWFault(): Error occurred during processing.\n" . $errMsg; 626 642 } … … 651 667 if (($errMsg !~ /Connection refused/) && 652 668 ($errMsg !~ /No route to host/)) { 653 $LOG->warn(" Error occurred during processing. " . $errMsg);669 $LOG->warn("Thread ID (" . threads->tid() . "): Error occurred during processing. " . $errMsg); 654 670 Carp::carp __PACKAGE__ . "->_handleAgentFault(): Error occurred during processing.\n" . $errMsg; 655 671 } … … 690 706 # perform the quick clone operation. 691 707 if (!defined($self->{'config'})) { 692 $LOG->info(" Quick cloning master VM (" . $self->{'master_vm_config'} . ").");708 $LOG->info("Thread ID (" . threads->tid() . "): Quick cloning master VM (" . $self->{'master_vm_config'} . ")."); 693 709 $som = $self->{'_vm_handle'}->quickCloneVM(src_config => $self->{'master_vm_config'}); 694 710 $ret = $som->result(); 695 711 if (!$ret) { 696 $LOG->fatal(" Unable to quick clone master VM (" . $self->{'master_vm_config'} . ").");712 $LOG->fatal("Thread ID (" . threads->tid() . "): Unable to quick clone master VM (" . $self->{'master_vm_config'} . ")."); 697 713 Carp::croak "Unable to quick clone master VM (" . $self->{'master_vm_config'} . ")."; 698 714 } … … 700 716 $self->{'config'} = $ret; 701 717 } else { 702 $LOG->debug(" Starting clone VM (" . $self->{'config'} . ").");718 $LOG->debug("Thread ID (" . threads->tid() . "): Starting clone VM (" . $self->{'config'} . ")."); 703 719 $som = $self->{'_vm_handle'}->startVM(config => $self->{'config'}); 704 720 $ret = $som->result(); 705 721 if (!$ret) { 706 $LOG->fatal(" Unable to start clone VM (" . $self->{'config'} . ").");722 $LOG->fatal("Thread ID (" . threads->tid() . "): Unable to start clone VM (" . $self->{'config'} . ")."); 707 723 Carp::croak "Unable to start clone VM (" . $self->{'config'} . ")."; 708 724 } … … 711 727 712 728 # Wait until the VM gets registered, before proceeding. 713 $LOG->debug(" Checking if clone VM (" . $self->{'config'} . ") is registered.");729 $LOG->debug("Thread ID (" . threads->tid() . "): Checking if clone VM (" . $self->{'config'} . ") is registered."); 714 730 $ret = undef; 715 731 while (!defined($ret) or !$ret) { … … 725 741 726 742 # Once registered, check if the VM is ON yet. 727 $LOG->debug(" Checking if clone VM (" . $self->{'config'} . ") is powered on.");743 $LOG->debug("Thread ID (" . threads->tid() . "): Checking if clone VM (" . $self->{'config'} . ") is powered on."); 728 744 $ret = undef; 729 745 while (!defined($ret) or ($ret != VM_EXECUTION_STATE_ON)) { … … 739 755 740 756 # Now, get the VM's MAC address. 741 $LOG->debug(" Retrieving MAC address of clone VM (" . $self->{'config'} . ").");757 $LOG->debug("Thread ID (" . threads->tid() . "): Retrieving MAC address of clone VM (" . $self->{'config'} . ")."); 742 758 $som = $self->{'_vm_handle'}->getMACaddrVM(config => $self->{'config'}); 743 759 $self->{'mac_address'} = $som->result(); 744 760 745 761 # Now, get the VM's name. 746 $LOG->debug(" Retrieving name of clone VM (" . $self->{'config'} . ").");762 $LOG->debug("Thread ID (" . threads->tid() . "): Retrieving name of clone VM (" . $self->{'config'} . ")."); 747 763 $som = $self->{'_vm_handle'}->getNameVM(config => $self->{'config'}); 748 764 $self->{'name'} = $som->result(); 749 765 750 766 # Now, get the VM's IP address. 751 $LOG->info(" Waiting for a valid IP address of clone VM (" . $self->{'config'} . ").");767 $LOG->info("Thread ID (" . threads->tid() . "): Waiting for a valid IP address of clone VM (" . $self->{'config'} . ")."); 752 768 $ret = undef; 753 769 my $logMsgPrinted = 0; … … 761 777 next; # skip further processing 762 778 } elsif (!$logMsgPrinted) { 763 $LOG->info(" Initialized clone VM (" . $self->{'name'} . ") using IP (" .779 $LOG->info("Thread ID (" . threads->tid() . "): Initialized clone VM (" . $self->{'name'} . ") using IP (" . 764 780 $self->{'ip_address'} . ") and MAC (" . $self->{'mac_address'} . ")."); 765 781 … … 767 783 $self->_allowNetwork(); 768 784 769 $LOG->info(" Waiting for Agent daemon to initialize inside clone VM.");785 $LOG->info("Thread ID (" . threads->tid() . "): Waiting for Agent daemon to initialize inside clone VM."); 770 786 $logMsgPrinted = 1; 771 787 } … … 822 838 # When given a hashtable reference, this function will extract a valid key 823 839 # from the hashtable and delete the (key, value) pair from the 824 # hashtable. The linkwith the highest score is returned.840 # hashtable. The key with the highest score is returned. 825 841 # 826 842 # Inputs: hashref … … 871 887 872 888 # Croak if no valid argument is supplied. 873 $LOG->error(" Error: No status argument supplied.");889 $LOG->error("Thread ID (" . threads->tid() . "): Error: No status argument supplied."); 874 890 Carp::croak "Error: No status argument supplied."; 875 891 } … … 898 914 899 915 # Warn if no valid fingerprint is supplied. 900 $LOG->warn(" (" . $self->{'name'} . ") - No valid fingerprint found.");916 $LOG->warn("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - No valid fingerprint found."); 901 917 Carp::carp __PACKAGE__ . "->_changeStatus(): (" . $self->{'name'} . ") - No valid fingerprint found."; 902 918 … … 912 928 # Mark the VM as suspicious indirectly, by inserting the fingerprint. 913 929 914 $LOG->info(" (" . $self->{'name'} . ") - Inserting Fingerprint Into Database.");930 $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Inserting Fingerprint Into Database."); 915 931 # Make sure the fingerprint contains a client_id. 916 932 $args{'fingerprint'}->{'client_id'} = $self->{'database_id'}; … … 920 936 }; 921 937 if ($@ || ($fingerprint_id == 0) || !defined($fingerprint_id)) { 922 $LOG->warn(" (" . $self->{'name'} . ") - Failure Inserting Fingerprint: " . $@);938 $LOG->warn("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Failure Inserting Fingerprint: " . $@); 923 939 } else { 924 $LOG->info(" (" . $self->{'name'} . ") - Database Insert Successful.");940 $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Database Insert Successful."); 925 941 } 926 942 } … … 952 968 if (length($COMPROMISE_FILE) > 0 && 953 969 defined($fingerprint)) { 954 $LOG->info(" Saving fingerprint to '" . $COMPROMISE_FILE . "'.");970 $LOG->info("Thread ID (" . threads->tid() . "): Saving fingerprint to '" . $COMPROMISE_FILE . "'."); 955 971 my $dump_file = new IO::File($COMPROMISE_FILE, "a"); 956 972 … … 998 1014 }; 999 1015 1000 $LOG->info(" Allowing VM (" . $self->{'name'} . ") network access.");1016 $LOG->info("Thread ID (" . threads->tid() . "): Allowing VM (" . $self->{'name'} . ") network access."); 1001 1017 # XXX: Currently, faults get propagated -- is this okay? 1002 1018 $self->{'_fw_handle'}->addChain($netTable); … … 1044 1060 }; 1045 1061 1046 $LOG->info(" Denying VM (" . $self->{'name'} . ") network access.");1062 $LOG->info("Thread ID (" . threads->tid() . "): Denying VM (" . $self->{'name'} . ") network access."); 1047 1063 # XXX: Currently, faults get propagated -- is this okay? 1048 1064 $self->{'_fw_handle'}->deleteRules($netTable); … … 1066 1082 1067 1083 if ($datastore_attr->{bavail} < $min_space_free) { 1068 $LOG->warn(" Directory (" . $datastore_path . ") has low disk space (" . $datastore_attr->{bavail} . " GB).");1084 $LOG->warn("Thread ID (" . threads->tid() . "): Directory (" . $datastore_path . ") has low disk space (" . $datastore_attr->{bavail} . " GB)."); 1069 1085 } elsif ($snapshot_attr->{bavail} < $min_space_free) { 1070 $LOG->warn(" Directory (" . $snapshot_path . ") has low disk space (" . $snapshot_attr->{bavail} . " GB).");1086 $LOG->warn("Thread ID (" . threads->tid() . "): Directory (" . $snapshot_path . ") has low disk space (" . $snapshot_attr->{bavail} . " GB)."); 1071 1087 } else { 1072 1088 return; 1073 1089 } 1074 $LOG->info(" Low disk space detected. Shutting down.");1090 $LOG->info("Thread ID (" . threads->tid() . "): Low disk space detected. Shutting down."); 1075 1091 exit; 1076 1092 } … … 1296 1312 # Now, assign our object the appropriate namespace. 1297 1313 bless $self, $class; 1314 1315 # Lock access to the $OBJECT_COUNT variable. 1316 $OBJECT_COUNT_SEMAPHORE->down(); 1298 1317 1299 1318 # Upon first use, start up a global instance of the VM manager. … … 1302 1321 $OBJECT_COUNT = 0; 1303 1322 } 1323 1324 # Unlock access to the $OBJECT_COUNT variable. 1325 $OBJECT_COUNT_SEMAPHORE->up(); 1304 1326 1305 1327 # Set a valid handle for the VM daemon. … … 1313 1335 my $caller = caller(); 1314 1336 if (($caller ne __PACKAGE__) && ($caller ne "HoneyClient::Manager")) { 1315 $LOG->info(" Installing default firewall rules.");1337 $LOG->info("Thread ID (" . threads->tid() . "): Installing default firewall rules."); 1316 1338 # XXX: Currently, faults get propagated -- is this okay? 1317 1339 $self->{'_fw_handle'}->installDefaultRules(); … … 1327 1349 # set the master VM to prepare for cloning. 1328 1350 unless (defined($self->{'config'})) { 1329 $LOG->info(" Setting VM (" . $self->{'master_vm_config'} . ") as master.");1351 $LOG->info("Thread ID (" . threads->tid() . "): Setting VM (" . $self->{'master_vm_config'} . ") as master."); 1330 1352 my $som = $self->{'_vm_handle'}->setMasterVM(config => $self->{'master_vm_config'}); 1331 1353 if (!$som->result()) { 1332 $LOG->fatal(" Unable to set VM (" . $self->{'master_vm_config'} . ") as a master VM.");1354 $LOG->fatal("Thread ID (" . threads->tid() . "): Unable to set VM (" . $self->{'master_vm_config'} . ") as a master VM."); 1333 1355 Carp::croak "Unable to set VM (" . $self->{'master_vm_config'} . ") as a master VM."; 1334 1356 } 1335 1357 } 1358 1359 # Lock access to the $OBJECT_COUNT variable. 1360 $OBJECT_COUNT_SEMAPHORE->down(); 1336 1361 1337 1362 # Update our global object count. 1338 1363 $OBJECT_COUNT++; 1364 1365 # Unlock access to the $OBJECT_COUNT variable. 1366 $OBJECT_COUNT_SEMAPHORE->up(); 1339 1367 1340 1368 # Finally, return the blessed object, with a fully initialized … … 1493 1521 $self->{'config'} = undef; 1494 1522 1495 $LOG->info(" Suspending clone VM (" . $vmConfig . ").");1523 $LOG->info("Thread ID (" . threads->tid() . "): Suspending clone VM (" . $vmConfig . ")."); 1496 1524 my $som = $self->{'_vm_handle'}->suspendVM(config => $vmConfig); 1497 1525 1498 1526 if (!defined($som)) { 1499 $LOG->error(" Unable to suspend VM (" . $self->{'config'} . ").");1527 $LOG->error("Thread ID (" . threads->tid() . "): Unable to suspend VM (" . $self->{'config'} . ")."); 1500 1528 $self->_changeStatus(status => "error"); 1501 1529 } else { … … 1513 1541 } 1514 1542 if (!defined($som)) { 1515 $LOG->error(" Unable to archive VM (" . $vmConfig . ").");1543 $LOG->error("Thread ID (" . threads->tid() . "): Unable to archive VM (" . $vmConfig . ")."); 1516 1544 } 1517 1545 } … … 1639 1667 1640 1668 # Croak if no valid argument is supplied. 1641 $LOG->error(" Error: No work argument supplied.");1669 $LOG->error("Thread ID (" . threads->tid() . "): Error: No work argument supplied."); 1642 1670 Carp::croak "Error: No work argument supplied."; 1643 1671 } … … 1673 1701 # Drive the Agent. 1674 1702 eval { 1675 $LOG->info(" (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Driving To Resource: " . $currentWork);1703 $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Driving To Resource: " . $currentWork); 1676 1704 $som = $self->{'_agent_handle'}->drive(driver_name => $self->{'driver_name'}, 1677 1705 parameters => encode_base64($currentWork)); … … 1681 1709 # We lost communications with the Agent; assume the worst 1682 1710 # and mark the VM as suspicious. 1683 $LOG->warn(" (" . $self->{'name'} . ") - Lost Communication with Agent! Assuming Integrity Failure.");1711 $LOG->warn("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Lost Communication with Agent! Assuming Integrity Failure."); 1684 1712 1685 1713 # Suspend and archive the cloned VM. … … 1693 1721 if (defined($self->{'database_id'})) { 1694 1722 $numWorkInserted = HoneyClient::Manager::Database::insert_history_urls($finishedWork); 1695 $LOG->info( $numWorkInserted . " URL(s) Inserted.");1723 $LOG->info("Thread ID (" . threads->tid() . "): " . $numWorkInserted . " URL(s) Inserted."); 1696 1724 } 1697 1725 … … 1701 1729 # Figure out if there was a compromise found. 1702 1730 } elsif (scalar(@{$result->{'fingerprint'}->{os_processes}})) { 1703 $LOG->warn(" (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Integrity Check: FAILED");1731 $LOG->warn("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Integrity Check: FAILED"); 1704 1732 1705 1733 # Dump the fingerprint to a file, if need be. … … 1713 1741 if (defined($self->{'database_id'})) { 1714 1742 $numWorkInserted = HoneyClient::Manager::Database::insert_history_urls($finishedWork); 1715 $LOG->info( $numWorkInserted . " URL(s) Inserted.");1743 $LOG->info("Thread ID (" . threads->tid() . "): " . $numWorkInserted . " URL(s) Inserted."); 1716 1744 } 1717 1745 … … 1720 1748 1721 1749 } else { 1722 $LOG->info(" (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Integrity Check: PASSED");1750 $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - " . $self->{'driver_name'} . " - Integrity Check: PASSED"); 1723 1751 # If possibile, insert work history. 1724 1752 $finishedWork->{'links_visited'}->{$currentWork} = $result->{'time_at'}; 1725 1753 if (defined($self->{'database_id'})) { 1726 1754 $numWorkInserted = HoneyClient::Manager::Database::insert_history_urls($finishedWork); 1727 $LOG->info( $numWorkInserted . " URL(s) Inserted.");1755 $LOG->info("Thread ID (" . threads->tid() . "): " . $numWorkInserted . " URL(s) Inserted."); 1728 1756 } 1729 1757 }
