agent and manager do not seem to connect

Based upon your later ticket (#111), can I assume this issue has been resolved? Or, is this still an issue?

— Darien

Okay, so based upon your most recent ticket (#113), I assume this still is an issue. We can try to troubleshoot in this ticket, then.

First off, it appears the Manager is continuously calling this:

Calling getIPaddrVM()...

And, it looks like your /var/log/messages is populated with the VM's DHCP lease information. So, the next question I have is…

What are the permissions on your /var/log/messages ? Are they at least 644, so that the perl process can properly read from this log file?

— Darien

Darien, thanks for taking a look at this so quickly.

The /var/log/messages was only 600. I changed it to 644, but still encounter the same problem.

I am not sure whether the getIPaddrVM is the problem…maybe the function completes, but the following function call fails?

Christian

Actually, if the getIPaddrVM() call completes, then you should see a Result: line, like this:

Calling getIPaddrVM()...
Result: 10.0.0.129

The fact that you're not seeing the Result: line indicates that this is the call that's failing. In other words, the Manager is having a trouble figuring out the IP address of the clone that just got created. If you chmod'd the /var/log/messages to 644, then by definition, the perl process should have at least read access to this logfile, which means that the next time you run StartManager.pl, it should work.

If you have StartManager.pl still running and you did chmod 644 /var/log/messages while it was still running, you'll probably have to restart the process in order to have it proceed further.

If StartManager.pl is still hanging at this step, then you need to verify that these types of DHCP log entries are properly recorded in your /var/log/messages file:

Aug 30 15:10:53 honeyclient3 vmnet-dhcpd: DHCPDISCOVER from 00:0c:29:5e:08:b1 via vmnet1
Aug 30 15:10:54 honeyclient3 vmnet-dhcpd: DHCPOFFER on 10.0.0.202 to 00:0c:29:5e:08:b1 via vmnet1
Aug 30 15:10:54 honeyclient3 vmnet-dhcpd: DHCPREQUEST for 10.0.0.202 from 00:0c:29:5e:08:b1 via vmnet1
Aug 30 15:10:54 honeyclient3 vmnet-dhcpd: DHCPACK on 10.0.0.202 to 00:0c:29:5e:08:b1 via vmnet1

Lastly, if you're seeing these entries and StartManager.pl still isn't working properly, then I'd recommend you manually run the HC::Manager::VM unit tests by typing the following command, from the directory where the HC::Manager tar.gz file was extracted:

perl -Ilib/ t/honeyclient_manager_vm.t

Darien, I only see two lines in the messages log:

Oct 2 15:01:54 localhost vmnet-dhcpd: DHCPREQUEST for 10.0.0.128 from 00:0c:29:0f:31:e4 via vmnet1 Oct 2 15:01:54 localhost vmnet-dhcpd: DHCPACK on 10.0.0.128 to 00:0c:29:0f:31:e4 via vmnet1

…but there is the mac and IP, so it should be able to figure it out.

Regards the unit tests, I am having some problems….executing the line, just makes it sit there forever…

oh - also take a look at 109 — this is when i initially reported unit test failures on the manager…

Replying to anonymous:

oh - also take a look at 109 — this is when i initially reported unit test failures on the manager…

Yes, those unit tests you ran for ticket #109 didn't pass. That tells me there might be an issue with the HC::Manager::VM module and we need to re-run those unit tests manually.

So, as I said before, go to your directory where you've extracted the HC::Manager .tar.gz file, cd into it, make sure your etc/honeyclient.xml is correct, and run the following manual unit test command:

perl -Ilib/ t/honeyclient_manager_vm.t

When you're prompted to run the basic and extended tests, please answer "yes" to both.

Then, please paste the output in a wiki code block, like this:

OUTPUT

— Darien

Darien, here a bit more information on this.

First, I was able to run the unit test. I had to make a few adjustments in order to get it to run (copy the edited honeyclient.xml into etc/; change the permissions on the test vmware image, install threads and threads::shared). Still some are failing:

[root@localhost HoneyClient-Manager-0.99]#  perl -Ilib/ t/honeyclient_manager_vm.t
ok 1 - use ExtUtils::MakeMaker;
ok 2 - use Log::Log4perl;
ok 3 - use HoneyClient::Util::Config;
ok 4 - use HoneyClient::Manager::VM;
ok 5 - use HoneyClient::Util::SOAP;
ok 6 - use File::Basename;
ok 7 - use File::Copy::Recursive;
ok 8 - use Data::Dumper;
ok 9 - use File::stat;
ok 10 - use Digest::MD5;
ok 11 - use DateTime::HiRes;
ok 12 - use Fcntl;
ok 13 - use VMware::VmPerl;
ok 14 - use VMware::VmPerl::Server;
ok 15 - use VMware::VmPerl::ConnectParams;
ok 16 - use VMware::VmPerl::VM;
ok 17 - use VMware::VmPerl::Question;
ok 18 - use threads;
ok 19 - use threads::shared;
ok 20 - use Thread::Queue;
ok 21 - use Thread::Semaphore;
ok 22 - require ExtUtils::MakeMaker;
ok 23 - ExtUtils::MakeMaker->can('prompt')
# About to run basic unit tests.
# Note: These tests *expect* VMware Server or VMware GSX to be installed and running on this system beforehand.
# Do you want to run basic tests? [yes] yes
ok 24 - require Log::Log4perl;
ok 25 - require HoneyClient::Util::Config;
ok 26 - HoneyClient::Util::Config->can('getVar')
ok 27 - require HoneyClient::Manager::VM;
ok 28 - HoneyClient::Manager::VM->can('init')
ok 29 - HoneyClient::Manager::VM->can('destroy')
ok 30 - require HoneyClient::Util::SOAP;
ok 31 - HoneyClient::Util::SOAP->can('getServerHandle')
ok 32 - HoneyClient::Util::SOAP->can('getClientHandle')
ok 33 - require File::Basename;
ok 34 - File::Basename->can('dirname')
ok 35 - File::Basename->can('basename')
ok 36 - require File::Copy::Recursive;
ok 37 - File::Copy::Recursive->can('dircopy')
ok 38 - File::Copy::Recursive->can('pathrmdir')
ok 39 - require Data::Dumper;
ok 40 - require File::stat;
ok 41 - require Digest::MD5;
ok 42 - Digest::MD5->can('md5_hex')
ok 43 - require DateTime::HiRes;
ok 44 - require Fcntl;
ok 45 - require VMware::VmPerl;
ok 46 - require VMware::VmPerl::Server;
ok 47 - require VMware::VmPerl::ConnectParams;
ok 48 - require VMware::VmPerl::VM;
ok 49 - require VMware::VmPerl::Question;
ok 50 - require threads;
ok 51 - require threads::shared;
ok 52 - require Thread::Queue;
ok 53 - require Thread::Semaphore;
# About to run extended tests.
# Note: These extended tests will take *significant* time to complete (10-30 minutes).
# Do you want to run extended tests? [no] yes
ok 54 - init()
ok 55 - destroy()
ok 56 - isRegisteredVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 57 - isRegisteredVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 58 - enumerate()
ok 59 - getStateVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 60 - startVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 61 - startVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 62 - stopVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 63 - stopVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 64 - rebootVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 65 - rebootVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 66 - suspendVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 67 - suspendVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 68 - fullCloneVM(src_config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx', dest_dir => '/root/HoneyClient-Manager-0.99/t/test_vm_clone')
ok 69 - fullCloneVM(src_config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx', dest_dir => '/root/HoneyClient-Manager-0.99/t/test_vm_clone')
Perl exited with active threads:
        0 running and unjoined
        1 finished and unjoined
        0 running and detached
ok 70 - getNameVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 71 - setNameVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx', name => 'newVM')
ok 72 - setNameVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx', name => 'newVM')
ok 73 - getMACaddrVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 74 - getIPaddrVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 75 - registerVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 76 - registerVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 77 - unregisterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 78 - unregisterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')
ok 79 - answerVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 80 - destroyVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 81 - destroyVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
Perl exited with active threads:
        0 running and unjoined
        1 finished and unjoined
        0 running and detached
ok 82 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 83 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 84 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 85 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 86 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
ok 87 - setMasterVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx')
Perl exited with active threads:
        0 running and unjoined
        1 finished and unjoined
        0 running and detached
ok 88 - quickCloneVM(src_config => '/root/HoneyClient-Manager-0.99/t/test_vm_master/winXPPro.vmx', dest_dir => '/root/HoneyClient-Manager-0.99/t/test_vm_clone')
Perl exited with active threads:
        0 running and unjoined
        2 finished and unjoined
        0 running and detached
not ok 89 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->rebootVM(): Could not reboot VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->rebootVM(): {'err' => bless( {'errNo' => '-8','errStr' => 'Invalid operation for virtual machine\'s current state: The requested operation ("reset") could not be completed because it conflicted with the state of the virtual machine ("off") at the time the request was received.  This error often occurs because the state of the virtual machine changed before it received the request.'}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->rebootVM(): Could not reboot VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->rebootVM(): {'err' => bless( {'errNo' => '-8','errStr' => 'Invalid operation for virtual machine\'s current state: The requested operation ("reset") could not be completed because it conflicted with the state of the virtual machine ("off") at the time the request was received.  This error often occurs because the state of the virtual machine changed before it received the request.'}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1217.
ok 90 - snapshotVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx', snapshot_file => '/root/HoneyClient-Manager-0.99/t/test_vm_clone.tar.gz')
ok 91 - snapshotVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx', snapshot_file => '/root/HoneyClient-Manager-0.99/t/test_vm_clone.tar.gz')
Perl exited with active threads:
        0 running and unjoined
        3 finished and unjoined
        0 running and detached
not ok 92 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1329.
Perl exited with active threads:
        0 running and unjoined
        1 finished and unjoined
        0 running and detached
not ok 93 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Encountered unknown question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '103159066','errStr' => 'A redo log for disk "/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmdk" was found but the disk is marked as persistent. Select an action for the redo log. '}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Encountered unknown question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '103159066','errStr' => 'A redo log for disk "/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmdk" was found but the disk is marked as persistent. Select an action for the redo log. '}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1440.
1..93
# Looks like you failed 3 tests of 93.
[root@localhost HoneyClient-Manager-0.99]#

I also doubleshecked the messages.log. It is readable and shows the following output:

Oct  3 10:47:42 localhost vmnet-dhcpd: DHCPDISCOVER from 00:0c:29:12:a5:79 via vmnet1
Oct  3 10:47:43 localhost vmnet-dhcpd: DHCPOFFER on 10.0.0.128 to 00:0c:29:12:a5:79 via vmnet1
Oct  3 10:47:43 localhost vmnet-dhcpd: DHCPREQUEST for 10.0.0.128 from 00:0c:29:12:a5:79 via vmnet1
Oct  3 10:47:43 localhost vmnet-dhcpd: DHCPACK on 10.0.0.128 to 00:0c:29:12:a5:79 via vmnet1

Running the actual manager, there is no change. It still hangs on the code trying to get the IP address.

Based on the unit tests you've pasted, it looks like getIPaddrVM() is not necessarily the issue. Otherwise test 74 would not have passed:

ok 74 - getIPaddrVM(config => '/root/HoneyClient-Manager-0.99/t/test_vm/winXPPro.vmx')

But it did pass. So let's assume that there's something else at work and see if we can resolve the other unit tests failures. The logic being is that if we can fix those, chance are, StartManager.pl will then work properly.

Let's go through each of the failures, one-by-one.

The three failures are 89, 92, and 93.

not ok 89 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->rebootVM(): Could not reboot VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->rebootVM(): {'err' => bless( {'errNo' => '-8','errStr' => 'Invalid operation for virtual machine\'s current state: The requested operation ("reset") could not be completed because it conflicted with the state of the virtual machine ("off") at the time the request was received.  This error often occurs because the state of the virtual machine changed before it received the request.'}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->rebootVM(): Could not reboot VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->rebootVM(): {'err' => bless( {'errNo' => '-8','errStr' => 'Invalid operation for virtual machine\'s current state: The requested operation ("reset") could not be completed because it conflicted with the state of the virtual machine ("off") at the time the request was received.  This error often occurs because the state of the virtual machine changed before it received the request.'}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1217.

This looks almost like a timing issue… When you ran these unit tests, was the server under any amount of user load? Were there other VMs running simultaneously (that were not being created by the code itself)?

It appears that these next 2 errors were cascading failures from test 89 failing. Meaning, if we fix test 89, then these next two should subside as well.

Also, if you had to change the permissions on the test_vm* directory, then chances are, you may need to give more permissive permissions across the entire package; all subdirectories should be chmod 755 and (most) files should be chmod 644. Otherwise, you could change the ownership of the extracted package directory to the user:group who is actually running the unit tests.

not ok 92 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1329.

not ok 93 - HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Encountered unknown question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '103159066','errStr' => 'A redo log for disk "/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmdk" was found but the disk is marked as persistent. Select an action for the redo log. '}, 'err' )}
#
#   Failed test 'HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
# HoneyClient::Manager::VM->answerVM(): Encountered unknown question for VM (/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmx).
# HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '103159066','errStr' => 'A redo log for disk "/root/HoneyClient-Manager-0.99/t/test_vm_clone/winXPPro.vmdk" was found but the disk is marked as persistent. Select an action for the redo log. '}, 'err' )}
# '
#   at t/honeyclient_manager_vm.t line 1440.

Hope this helps,

— Darien

Turns out that the messages log file was simply very big and parsing took forever. Deleting the messages log file leads to the Manager obtaining the VM IP correctly. Marking issue as fixed. Christian