Changeset 1547 for honeyclient

Show
Ignore:
Timestamp:
04/22/08 02:22:00 (7 months ago)
Author:
kindlund
Message:

Added initial support for managing simultaneous honeyclient VMs on a single Manager. Command-line functionality is complete; however, Database functionality is NOT complete. Initial stress tests and unit tests seem to pass ok. Had to re-work some of the VM daemon functionality, in order for multiple threads to play nice. ithreads is still very annoying to use — 80% of the time it works ok, but the remaining 20% of the time seems to cause the code to run into esoteric corner cases (e.g., initialization/destruction logic) that takes LONG amounts of time to debug.

Files:

Legend:

Unmodified
Added
Removed
Modified
Copied
Moved
  • honeyclient/trunk/etc/honeyclient.xml

    r1538 r1547  
    178178    </Crawler> 
    179179    <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> 
    180183        <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."> 
    181184            fingerprint.dump 
  • honeyclient/trunk/lib/HoneyClient/Manager.pm

    r1499 r1547  
    287287our $LOG = get_logger(); 
    288288 
     289# The global work queue.  Each entry represents 
     290# work destined for a child thread worker. 
     291our $WORK_QUEUE : shared = undef; 
     292 
     293# The global wait queue.  Each entry represents 
     294# a thread ID waiting for more work. 
     295our $WAIT_QUEUE : shared = undef; 
     296 
    289297####################################################################### 
    290298# Daemon Initialization / Destruction                                 # 
     
    418426    }; 
    419427 
     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 
    420451    # XXX: There is an issue where if we try to quit but are in the 
    421452    # process of asynchronously archiving a VM, then the async archive 
     
    425456    kill("KILL", -$$); 
    426457} 
     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 
     466sub _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. 
     492sub _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. 
     545sub _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; 
    427555 
    428556####################################################################### 
     
    496624    } 
    497625 
    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    } 
    500645 
    501646    # If supported, get a URL list from the database. 
    502647    my $remoteLinksExist = 0; 
    503648    my $queue_url_list = {}; 
    504     while (defined($vm->database_id)) { 
     649    my $tid = undef; 
     650    while (getVar(name      => "enable", 
     651                  namespace => "HoneyClient::Manager::Database")) { 
    505652        $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); 
    507656        $remoteLinksExist = scalar(%{$queue_url_list}); 
    508657        while (!$localLinksExist && !$remoteLinksExist) { 
     
    512661            # XXX: Trap/ignore all errors and simply retry. 
    513662            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); 
    515666                $remoteLinksExist = scalar(%{$queue_url_list}); 
    516667            }; 
     
    522673        } 
    523674         
    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 
    526700        # Once finished, empty the work queue. 
    527701        $args{'work'} = {}; 
     
    535709    # that was provided from the command line and then shut down. 
    536710    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        } 
    538742        # Once finished, empty the work queue. 
    539743        $args{'work'} = {}; 
    540744    } 
    541745    $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. 
     751sub _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(); 
    542842} 
    543843 
  • honeyclient/trunk/lib/HoneyClient/Manager/VM.pm

    r1518 r1547  
    613613# used to guarantee only one operation per VM is performed 
    614614# at any given time. 
    615 our %vmSemaphoreHash
     615our %vmSemaphoreHash : shared
    616616 
    617617# Global semaphore, designed to limit exclusive access 
     
    23042304            $vmSemaphore->up(); 
    23052305            $maxThreadSemaphore->up(); 
    2306             return
     2306            threads->exit()
    23072307        }; 
    23082308 
     
    23632363         
    23642364        $maxThreadSemaphore->up(); 
    2365         return
     2365        threads->exit()
    23662366    }; 
    23672367 
     
    41014101#            $vmSemaphore->up(); 
    41024102#            $maxThreadSemaphore->up(); 
    4103 #            return
     4103#            threads->exit()
    41044104#        }; 
    41054105# 
     
    41704170# 
    41714171#        $maxThreadSemaphore->up(); 
    4172 #        return
     4172#        threads->exit()
    41734173#    }; 
    41744174 
     
    43784378 
    43794379    # 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. 
    43814393    my $thread = async { 
    43824394 
     
    43994411            $vmSemaphore->up(); 
    44004412            $maxThreadSemaphore->up(); 
    4401             return
     4413            threads->exit()
    44024414        }; 
    44034415 
     
    44074419        # Yes, this is annoying and ugly. 
    44084420        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 ensure 
    4418             # it doesn't get used while we snapshot it. 
    4419             _callback($class, "unregisterVM", %args); 
    44204421 
    44214422            # Lock the VM. 
     
    44324433            chdir $pwd; 
    44334434 
    4434             # Unlock chdirSemaphore. 
    4435             $chdirSemaphore->up(); 
    44364435 
    44374436            if (system(getVar(name => "bin_tar"), '-C', $parentDir, '-zcpf', $args{'snapshot_file'}, @fileList) != 0) { 
    44384437                # Unlock VM, if fail. 
     4438                $chdirSemaphore->up(); 
    44394439                $vmSemaphore->up(); 
    44404440                $LOG->warn("Could not snapshot VM to ($args{'snapshot_file'}). " . 
     
    44464446                                             'err'); 
    44474447            } 
     4448 
     4449            # Unlock chdirSemaphore. 
     4450            $chdirSemaphore->up(); 
    44484451             
    44494452            # Unlock the VM. 
     
    44654468        } 
    44664469        $maxThreadSemaphore->up(); 
    4467         return
     4470        threads->exit()
    44684471    }; 
    44694472 
     
    47074710            $LOG->warn("Asynchronous revert of ($vmDir) interrupted!"); 
    47084711            $maxThreadSemaphore->up(); 
    4709             return
     4712            threads->exit()
    47104713        }; 
    47114714 
     
    47644767        } 
    47654768        $maxThreadSemaphore->up(); 
    4766         return
     4769        threads->exit()
    47674770    }; 
    47684771 
  • honeyclient/trunk/lib/HoneyClient/Manager/VM/Clone.pm

    r1499 r1547  
    303303use threads::shared; 
    304304 
     305# Make sure Thread::Semaphore loads. 
     306BEGIN { 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."); } 
     307require_ok('Thread::Semaphore'); 
     308use Thread::Semaphore; 
     309 
    305310# Make sure File::Basename loads. 
    306311BEGIN { 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."); } 
     
    345350use threads; 
    346351use threads::shared; 
     352use Thread::Semaphore; 
    347353 
    348354# Include Global Configuration Processing Library 
     
    386392# Clone objects that have been created. 
    387393our $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. 
     398our $OBJECT_COUNT_SEMAPHORE = Thread::Semaphore->new(1); 
    388399 
    389400# Include Database Libraries 
     
    559570                                                fault_handler => sub { die "ERROR"; }); 
    560571 
    561         $LOG->info("Suspending clone VM (" . $self->{'config'} . ")."); 
     572        $LOG->info("Thread ID (" . threads->tid() . "): Suspending clone VM (" . $self->{'config'} . ")."); 
    562573        my $som = undef; 
    563574        eval { 
     
    568579        # a CTRL-C or other forced termination. 
    569580        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 
    570586            # Make sure the VM daemon was properly destroyed. 
    571587            HoneyClient::Manager::VM->destroy(); 
     
    582598 
    583599        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'} . ")."); 
    585601            $self->_changeStatus(status => "error"); 
    586602        } else { 
     
    596612    # Upon termination, destroy the global instance of the VM manager. 
    597613    if ($OBJECT_COUNT == 0) { 
    598         $LOG->debug("Destroying VM daemon."); 
     614        $LOG->debug("Thread ID (" . threads->tid() . "): Destroying VM daemon."); 
    599615        HoneyClient::Manager::VM->destroy(); 
    600616    } 
     
    622638     
    623639    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); 
    625641        Carp::carp __PACKAGE__ . "->_handleFWFault(): Error occurred during processing.\n" . $errMsg; 
    626642    } 
     
    651667    if (($errMsg !~ /Connection refused/) && 
    652668        ($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); 
    654670        Carp::carp __PACKAGE__ . "->_handleAgentFault(): Error occurred during processing.\n" . $errMsg; 
    655671    } 
     
    690706    # perform the quick clone operation. 
    691707    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'} . ")."); 
    693709        $som = $self->{'_vm_handle'}->quickCloneVM(src_config => $self->{'master_vm_config'}); 
    694710        $ret = $som->result(); 
    695711        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'} . ")."); 
    697713            Carp::croak "Unable to quick clone master VM (" . $self->{'master_vm_config'} . ")."; 
    698714        } 
     
    700716        $self->{'config'} = $ret; 
    701717    } else { 
    702         $LOG->debug("Starting clone VM (" . $self->{'config'} . ")."); 
     718        $LOG->debug("Thread ID (" . threads->tid() . "): Starting clone VM (" . $self->{'config'} . ")."); 
    703719        $som = $self->{'_vm_handle'}->startVM(config => $self->{'config'}); 
    704720        $ret = $som->result(); 
    705721        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'} . ")."); 
    707723            Carp::croak "Unable to start clone VM (" . $self->{'config'} . ")."; 
    708724        } 
     
    711727 
    712728    # 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."); 
    714730    $ret = undef; 
    715731    while (!defined($ret) or !$ret) { 
     
    725741 
    726742    # 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."); 
    728744    $ret = undef; 
    729745    while (!defined($ret) or ($ret != VM_EXECUTION_STATE_ON)) { 
     
    739755 
    740756    # 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'} . ")."); 
    742758    $som = $self->{'_vm_handle'}->getMACaddrVM(config => $self->{'config'}); 
    743759    $self->{'mac_address'} = $som->result(); 
    744760 
    745761    # 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'} . ")."); 
    747763    $som = $self->{'_vm_handle'}->getNameVM(config => $self->{'config'}); 
    748764    $self->{'name'} = $som->result(); 
    749765 
    750766    # 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'} . ")."); 
    752768    $ret = undef; 
    753769    my $logMsgPrinted = 0; 
     
    761777            next; # skip further processing 
    762778        } 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 (" . 
    764780                       $self->{'ip_address'} . ") and MAC (" . $self->{'mac_address'} . ")."); 
    765781 
     
    767783            $self->_allowNetwork(); 
    768784 
    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."); 
    770786            $logMsgPrinted = 1; 
    771787        } 
     
    822838# When given a hashtable reference, this function will extract a valid key 
    823839# from the hashtable and delete the (key, value) pair from the 
    824 # hashtable.  The link with the highest score is returned. 
     840# hashtable.  The key with the highest score is returned. 
    825841# 
    826842# Inputs: hashref 
     
    871887 
    872888        # 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."); 
    874890        Carp::croak "Error: No status argument supplied."; 
    875891    } 
     
    898914 
    899915                    # 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."); 
    901917                    Carp::carp __PACKAGE__ . "->_changeStatus(): (" . $self->{'name'} . ") - No valid fingerprint found."; 
    902918 
     
    912928                    # Mark the VM as suspicious indirectly, by inserting the fingerprint. 
    913929 
    914                     $LOG->info("(" . $self->{'name'} . ") - Inserting Fingerprint Into Database."); 
     930                    $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Inserting Fingerprint Into Database."); 
    915931                    # Make sure the fingerprint contains a client_id. 
    916932                    $args{'fingerprint'}->{'client_id'} = $self->{'database_id'}; 
     
    920936                    }; 
    921937                    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: " . $@); 
    923939                    } else { 
    924                         $LOG->info("(" . $self->{'name'} . ") - Database Insert Successful."); 
     940                        $LOG->info("Thread ID (" . threads->tid() . "): (" . $self->{'name'} . ") - Database Insert Successful."); 
    925941                    } 
    926942                } 
     
    952968    if (length($COMPROMISE_FILE) > 0 && 
    953969        defined($fingerprint)) { 
    954         $LOG->info("Saving fingerprint to '" . $COMPROMISE_FILE . "'."); 
     970        $LOG->info("Thread ID (" . threads->tid() . "): Saving fingerprint to '" . $COMPROMISE_FILE . "'."); 
    955971        my $dump_file = new IO::File($COMPROMISE_FILE, "a"); 
    956972 
     
    9981014    }; 
    9991015 
    1000     $LOG->info("Allowing VM (" . $self->{'name'} . ") network access."); 
     1016    $LOG->info("Thread ID (" . threads->tid() . "): Allowing VM (" . $self->{'name'} . ") network access."); 
    10011017    # XXX: Currently, faults get propagated -- is this okay? 
    10021018    $self->{'_fw_handle'}->addChain($netTable); 
     
    10441060    }; 
    10451061 
    1046     $LOG->info("Denying VM (" . $self->{'name'} . ") network access."); 
     1062    $LOG->info("Thread ID (" . threads->tid() . "): Denying VM (" . $self->{'name'} . ") network access."); 
    10471063    # XXX: Currently, faults get propagated -- is this okay? 
    10481064    $self->{'_fw_handle'}->deleteRules($netTable); 
     
    10661082 
    10671083    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)."); 
    10691085    } 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)."); 
    10711087    } else { 
    10721088        return; 
    10731089    } 
    1074     $LOG->info("Low disk space detected. Shutting down."); 
     1090    $LOG->info("Thread ID (" . threads->tid() . "): Low disk space detected. Shutting down."); 
    10751091    exit; 
    10761092} 
     
    12961312    # Now, assign our object the appropriate namespace. 
    12971313    bless $self, $class; 
     1314     
     1315    # Lock access to the $OBJECT_COUNT variable. 
     1316    $OBJECT_COUNT_SEMAPHORE->down(); 
    12981317 
    12991318    # Upon first use, start up a global instance of the VM manager. 
     
    13021321        $OBJECT_COUNT = 0; 
    13031322    } 
     1323     
     1324    # Unlock access to the $OBJECT_COUNT variable. 
     1325    $OBJECT_COUNT_SEMAPHORE->up(); 
    13041326 
    13051327    # Set a valid handle for the VM daemon. 
     
    13131335    my $caller = caller(); 
    13141336    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."); 
    13161338        # XXX: Currently, faults get propagated -- is this okay? 
    13171339        $self->{'_fw_handle'}->installDefaultRules(); 
     
    13271349    # set the master VM to prepare for cloning. 
    13281350    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."); 
    13301352        my $som = $self->{'_vm_handle'}->setMasterVM(config => $self->{'master_vm_config'}); 
    13311353        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."); 
    13331355            Carp::croak "Unable to set VM (" . $self->{'master_vm_config'} . ") as a master VM."; 
    13341356        } 
    13351357    } 
     1358     
     1359    # Lock access to the $OBJECT_COUNT variable. 
     1360    $OBJECT_COUNT_SEMAPHORE->down(); 
    13361361 
    13371362    # Update our global object count. 
    13381363    $OBJECT_COUNT++; 
     1364     
     1365    # Unlock access to the $OBJECT_COUNT variable. 
     1366    $OBJECT_COUNT_SEMAPHORE->up(); 
    13391367 
    13401368    # Finally, return the blessed object, with a fully initialized 
     
    14931521    $self->{'config'} = undef; 
    14941522     
    1495     $LOG->info("Suspending clone VM (" . $vmConfig . ")."); 
     1523    $LOG->info("Thread ID (" . threads->tid() . "): Suspending clone VM (" . $vmConfig . ")."); 
    14961524    my $som = $self->{'_vm_handle'}->suspendVM(config => $vmConfig); 
    14971525 
    14981526    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'} . ")."); 
    15001528        $self->_changeStatus(status => "error"); 
    15011529    } else { 
     
    15131541        } 
    15141542        if (!defined($som)) { 
    1515             $LOG->error("Unable to archive VM (" . $vmConfig . ")."); 
     1543            $LOG->error("Thread ID (" . threads->tid() . "): Unable to archive VM (" . $vmConfig . ")."); 
    15161544        } 
    15171545    } 
     
    16391667 
    16401668        # 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."); 
    16421670        Carp::croak "Error: No work argument supplied."; 
    16431671    } 
     
    16731701        # Drive the Agent. 
    16741702        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); 
    16761704            $som = $self->{'_agent_handle'}->drive(driver_name => $self->{'driver_name'}, 
    16771705                                                   parameters  => encode_base64($currentWork)); 
     
    16811709            # We lost communications with the Agent; assume the worst 
    16821710            # 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."); 
    16841712 
    16851713            # Suspend and archive the cloned VM. 
     
    16931721            if (defined($self->{'database_id'})) { 
    16941722                $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."); 
    16961724            } 
    16971725 
     
    17011729        # Figure out if there was a compromise found. 
    17021730        } 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"); 
    17041732 
    17051733            # Dump the fingerprint to a file, if need be. 
     
    17131741            if (defined($self->{'database_id'})) { 
    17141742                $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."); 
    17161744            } 
    17171745 
     
    17201748 
    17211749        } 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"); 
    17231751            # If possibile, insert work history. 
    17241752            $finishedWork->{'links_visited'}->{$currentWork} = $result->{'time_at'}; 
    17251753            if (defined($self->{'database_id'})) { 
    17261754                $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."); 
    17281756            } 
    17291757        }