dkindlund / honeyclient

MITRE HoneyClient Project
http://www.honeyclient.org
GNU General Public License v2.0
8 stars 4 forks source link

StartManager.pl fails "Could not answer known question for VM[...]" #205

Closed dkindlund closed 14 years ago

dkindlund commented 14 years ago

When trying to start the HoneyClient Manager script on the host it fails and kills itself with the following output: {{{ hcuser@ubuntu:~/honeyclient$ perl -Ilib bin/StartManager.pl Starting new session... 2009-02-17 15:13:04 INFO HoneyClient::Manager::VM::init - Initializing VM daemon at PID: 7808 2009-02-17 15:13:05 INFO HoneyClient::Manager::VM::Clone::new - Setting VM (/vm/master/master.vmx) as master. 2009-02-17 15:13:18 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.vmx). 2009-02-17 15:13:52 WARN HoneyClient::Manager::VM::answerVM - Could not answer known question for VM (/vm/clones/476a3980b7d7927a9bc8702b75/master.vmx). (-16: Virtual machine requires user input to continue) 2009-02-17 15:13:52 ERROR HoneyClient::Util::SOAP::_handleFault - Error occurred during processing. HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/vm/clones/476a3980b7d7927a9bc8702b75/master.vmx). HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )} HoneyClient::Util::SOAP->handleFault(): Error occurred during processing. HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/vm/clones/476a3980b7d7927a9bc8702b75/master.vmx). HoneyClient::Manager::VM->answerVM(): {'err' => bless( {'errNo' => '-16','errStr' => 'Virtual machine requires user input to continue'}, 'err' )} Killed hcuser@ubuntu:~/honeyclient$ }}} It leaves a clone registered but inoperable. Un-registering the clone which shows up in {{{ $vmware-cmd -l /vm/firewall-3/honeywall.vmx /vm/clones/476a3980b7d7927a9bc8702b75/master.vmx }}}

After unregistering this listed clone, there is still a running clone process in memory shown by ps here: {{{ $ps ax | grep clone 7853 ? Ss 0:00 /usr/lib/vmware/bin/vmware-vmx -C /vm/clones/476a3980b7d7927a9bc8702b75/master.vmx -@ "" }}}


Running this command as root leads to the following output (I pressed Ctr-C after the SOAP server error occurred a few times): {{{ root@ubuntu:/home/user/honeyclient# perl -Ilib bin/StartManager.pl Starting new session... 2009-02-17 15:23:45 INFO HoneyClient::Manager::VM::init - Initializing VM daemon at PID: 7882 2009-02-17 15:23:46 INFO HoneyClient::Manager::VM::Clone::new - Setting VM (/vm/master/master.vmx) as master. 2009-02-17 15:23:59 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.vmx). 2009-02-17 15:24:57 INFO HoneyClient::Manager::VM::Clone::_init - Initialized clone VM (af01bbf0606fb0a094c19b243f) using IP (10.0.0.130) and MAC (00:0c:29:13:44:b6). 2009-02-17 15:25:19 WARN HoneyClient::Manager::VM::Clone::_handleFault - Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

HoneyClient::Manager::VM::Clone->_handleFault(): Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

at /usr/local/share/perl/5.8.8/SOAP/Lite.pm line 3412 2009-02-17 15:25:24 WARN HoneyClient::Manager::VM::Clone::_handleFault - Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

HoneyClient::Manager::VM::Clone->_handleFault(): Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

at /usr/local/share/perl/5.8.8/SOAP/Lite.pm line 3412 2009-02-17 15:25:28 WARN HoneyClient::Manager::VM::Clone::_handleFault - Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

HoneyClient::Manager::VM::Clone->_handleFault(): Error occurred during processing. soap:Client: Failed to locate method (getStatus) in class (HoneyClient::Agent) at /usr/lib/perl5/site_perl/5.10/SOAP/Lite.pm line 2586.

at /usr/local/share/perl/5.8.8/SOAP/Lite.pm line 3412 2009-02-17 15:25:30 INFO HoneyClient::Manager::_cleanup - Cleaning up. 2009-02-17 15:25:31 INFO HoneyClient::Manager::VM::Clone::DESTROY - Suspending clone VM (/vm/clones/af01bbf0606fb0a094c19b243f/master.vmx). 2009-02-17 15:25:32 INFO HoneyClient::Manager::VM::destroy - Destroying VM daemon at PID: 7882 2009-02-17 15:25:32 WARN HoneyClient::Manager::VM::destroy - Killing VM daemon at PID: 7882 2009-02-17 15:25:34 INFO HoneyClient::Manager::VM::init - Initializing VM daemon at PID: 7959 Killed }}} This also leaves a clone registered but allows it to be unregistered cleanly. {{{ root@ubuntu:/home/user/honeyclient# vmware-cmd -l /vm/firewall-3/honeywall.vmx /vm/clones/af01bbf0606fb0a094c19b243f/master.vmx root@ubuntu:/home/user/honeyclient# ps ax | grep vmware 7344 ? Ss 0:01 /usr/sbin/vmware-serverd 7496 ? Ss 0:00 /usr/bin/vmnet-natd -d /var/run/vmnet-natd-8.pid -m /var/run/vmnet-natd-8.mac -c /etc/vmware/vmnet8/nat/nat.conf 7528 ? Ss 0:00 /usr/bin/vmnet-dhcpd -cf /etc/vmware/vmnet1/dhcpd/dhcpd.conf -lf /etc/vmware/vmnet1/dhcpd/dhcpd.leases -pf /var/run/vmnet-dhcpd-vmnet1.pid vmnet1 7529 ? Ss 0:00 /usr/bin/vmnet-dhcpd -cf /etc/vmware/vmnet8/dhcpd/dhcpd.conf -lf /etc/vmware/vmnet8/dhcpd/dhcpd.leases -pf /var/run/vmnet-dhcpd-vmnet8.pid vmnet8 7559 pts/0 S 0:00 /bin/sh /usr/lib/vmware/lib/wrapper-gtk24.sh /usr/lib/vmware/lib /usr/lib/vmware/bin/vmware /usr/lib/vmware/libconf 7575 pts/0 S 0:02 /usr/lib/vmware/bin/vmware 7576 pts/0 S 0:00 /bin/sh /usr/lib/vmware/lib/wrapper-gtk24.sh /usr/lib/vmware/lib /usr/lib/vmware/bin/vmware /usr/lib/vmware/libconf 7707 ? S<sl 1:26 /usr/lib/vmware/bin/vmware-vmx -C /vm/firewall-3/honeywall.vmx -@ "" 7722 ? S< 0:06 [vmware-rtc] 7982 pts/1 S+ 0:00 grep vmware }}}

Any suggestions greatly appreciated. [[br]] Thanks

dkindlund commented 14 years ago

Author: kindlund Here's the crux of the problem:

{{{ 2009-02-17 15:13:52 WARN HoneyClient::Manager::VM::answerVM - Could not answer known question for VM (/vm/clones/476a3980b7d7927a9bc8702b75/master.vmx). (-16: Virtual machine requires user input to continue) 2009-02-17 15:13:52 ERROR HoneyClient::Util::SOAP::_handleFault - Error occurred during processing. HoneyClient::Manager::VM->answerVM(): Could not answer known question for VM (/vm/clones/476a3980b7d7927a9bc8702b75/master.vmx). }}}

When the Manager tries to clone your Master VM, VMware Server prompts for a question that the code has never seen before. In order to troubleshoot further, I need to know what the question text (along with question ID) looks like. This information is visible if you happen to connect to the newly created clone VM immediately after it gets created.

If that's not possible, upload the latest vmware.log file and I'll check to see if the prompt information is in there.

When this happens, to cleanup, you'll need to make sure the clone VM is shutdown (manually). Then, unregister the clone and then delete the clone VM directory.

-- Darien

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Log output below, it seems like a permissions issue but the /vm/master/master.vmx file and everything that goes with it belong to the user account that is running the script. {{{ root@ubuntu:/vm/clones/da58eb1b2725f3f4e4181e182a# cat vmware.log Feb 18 10:43:43: vmx| Log for VMware Server pid=5661 version=1.0.8 build=build-126538 option=Release Feb 18 10:43:43: vmx| Command line: "/usr/lib/vmware/bin/vmware-vmx" "-C" "-@" """" "/vm/clones/da58eb1b2725f3f4e4181e182a/master.vmx" Feb 18 10:43:43: vmx| vmxvmdb: Index name being generated from config file Feb 18 10:43:43: vmx| VMXVmdbConnectServerd - Trying to discover serverd Feb 18 10:43:43: vmx| MStat: Creating Stat system.cpuusage Feb 18 10:43:43: vmx| MStat: Creating Stat system.ram Feb 18 10:43:43: vmx| MStat: Creating Stat system.uptime Feb 18 10:43:43: vmx| MStat: Creating Stat system.load Feb 18 10:43:43: vmx| cpuids[0].id81.ecx = 0x1 Feb 18 10:43:43: vmx| cpuids[1].id81.ecx = 0x1 Feb 18 10:43:43: vmx| cpuids[2].id81.ecx = 0x1 Feb 18 10:43:43: vmx| cpuids[3].id81.ecx = 0x1 Feb 18 10:43:43: vmx| pcpu #0 CPUID numEntries=10 GenuntelineI Feb 18 10:43:43: vmx| pcpu #0 CPUID version=0x6fb id1.edx=0xbfebfbff id1.ecx=0xe3bd id1.ebx=0x40800 Feb 18 10:43:43: vmx| pcpu #0 CPUID id80.eax=80000008 id81.edx=0x20100000 id81.ecx=0x1 Feb 18 10:43:43: vmx| pcpu #1 CPUID numEntries=10 GenuntelineI Feb 18 10:43:43: vmx| pcpu #1 CPUID version=0x6fb id1.edx=0xbfebfbff id1.ecx=0xe3bd id1.ebx=0x1040800 Feb 18 10:43:43: vmx| pcpu #1 CPUID id80.eax=80000008 id81.edx=0x20100000 id81.ecx=0x1 Feb 18 10:43:43: vmx| pcpu #2 CPUID numEntries=10 GenuntelineI Feb 18 10:43:43: vmx| pcpu #2 CPUID version=0x6fb id1.edx=0xbfebfbff id1.ecx=0xe3bd id1.ebx=0x2040800 Feb 18 10:43:43: vmx| pcpu #2 CPUID id80.eax=80000008 id81.edx=0x20100000 id81.ecx=0x1 Feb 18 10:43:43: vmx| pcpu #3 CPUID numEntries=10 GenuntelineI Feb 18 10:43:43: vmx| pcpu #3 CPUID version=0x6fb id1.edx=0xbfebfbff id1.ecx=0xe3bd id1.ebx=0x3040800 Feb 18 10:43:43: vmx| pcpu #3 CPUID id80.eax=80000008 id81.edx=0x20100000 id81.ecx=0x1 Feb 18 10:43:43: vmx| CPUID id1.edx: 0xbfebfbff id1.ecx: 0xe3bd id81.edx: 0x20100000 id81.ecx: 0x1 Feb 18 10:43:43: vmx| CPUID id88.ecx: 0 id88.edx: 0 Feb 18 10:43:43: vmx| Setup symlink /var/run/vmware/%2Fvm%2Fclones%2Fda58eb1b2725f3f4e4181e182a%2Fmaster%2Evmx -> /var/run/vmware/user/5661 Feb 18 10:43:43: vmx| ACL_InitCapabilities: here 1 (bug 63252) Feb 18 10:43:43: vmx| changing directory to /vm/clones/da58eb1b2725f3f4e4181e182a/. Feb 18 10:43:43: vmx| Config file: /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmx Feb 18 10:43:43: vmx| LOG failed to remove /vm/clones/da58eb1b2725f3f4e4181e182a/vmware-2.log failed: No such file or directory Feb 18 10:43:43: vmx| Unable to find /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmss. Setting vmState to NULL. Feb 18 10:43:43: vmx| Read from FIFO 32 -- connecting to serverd... Feb 18 10:43:43: vmx| VMDB: Connected to serverd Feb 18 10:43:43: vmx| Accepted new connection at 54 for thread control (0x84d1360) Feb 18 10:43:43: vmx| VUINewControlConnection: before slow ACL gunk (bug 63252). Feb 18 10:43:43: vmx| ACL_InitCapabilities: here 2 (bug 63252) Feb 18 10:43:43: vmx| VUINewControlConnection: after slow ACL gunk (bug 63252). Feb 18 10:43:43: vmx| VUI: A new VMControl client connected. Feb 18 10:43:43: vmx| IPC version negotiation version: VMX returning 2.1 to control Feb 18 10:43:43: vmx| IPC vmcontrol-temp version: VMX returning 11.4 to control that tried 11.4 Feb 18 10:43:43: vmx| TOOLS delaying state change request to state 3 Feb 18 10:43:43: vmx| PowerOn Feb 18 10:43:43: vmx| Host ACPI: can't find SRAT Feb 18 10:43:43: vmx| Unable to find /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmss. Setting vmState to NULL. Feb 18 10:43:43: vmx| DISKUTIL: Offline toolsVersion = 6536 Feb 18 10:43:43: vmx| Msg_Hint: msg.upgrade.legacyVM (not shown) Feb 18 10:43:43: vmx| HOST sysname Linux, nodename ubuntu, release 2.6.22-14-server, version #1 SMP Tue Feb 12 08:27:05 UTC 2008, machine i686, SMP, hz=100 Feb 18 10:43:43: vmx| DICT --- USER PREFERENCES Feb 18 10:43:43: vmx| DICT pref.grabOnKeyPress = FALSE Feb 18 10:43:43: vmx| DICT pref.autoFitFullScreen = fitHostToGuest Feb 18 10:43:43: vmx| DICT pref.view.navBar.type = favorites Feb 18 10:43:43: vmx| DICT pref.mruDest0.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest0.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest0.user = Feb 18 10:43:43: vmx| DICT pref.mruDest1.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest1.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest1.user = Feb 18 10:43:43: vmx| DICT pref.mruDest2.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest2.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest2.user = Feb 18 10:43:43: vmx| DICT pref.mruDest3.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest3.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest3.user = Feb 18 10:43:43: vmx| DICT pref.mruDest4.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest4.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest4.user = Feb 18 10:43:43: vmx| DICT pref.mruDest5.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest5.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest5.user = Feb 18 10:43:43: vmx| DICT pref.mruDest6.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest6.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest6.user = Feb 18 10:43:43: vmx| DICT pref.mruDest7.present = FALSE Feb 18 10:43:43: vmx| DICT pref.mruDest7.destString = Feb 18 10:43:43: vmx| DICT pref.mruDest7.user = Feb 18 10:43:43: vmx| DICT webUpdate.checkPeriod = weekly Feb 18 10:43:43: vmx| DICT webUpdate.checkLast = 1234894515 Feb 18 10:43:43: vmx| DICT pref.console.openedObj0.present = FALSE Feb 18 10:43:43: vmx| DICT pref.console.openedObj0.type = vm Feb 18 10:43:43: vmx| DICT pref.console.openedObj0.path = /vm/#38073fb9fdd5820c/ Feb 18 10:43:43: vmx| DICT pref.console.openedObj0.file = /vm/master/master.vmx Feb 18 10:43:43: vmx| DICT pref.console.openedObj0.dest = /host2/#7f2f52b93ae2d99b/ Feb 18 10:43:43: vmx| DICT pref.console.openedObj.maxNum = 3 Feb 18 10:43:43: vmx| DICT pref.console.openedObj1.present = TRUE Feb 18 10:43:43: vmx| DICT pref.console.openedObj1.type = vm Feb 18 10:43:43: vmx| DICT pref.console.openedObj1.path = /vm/#3efaf2eafe8a2b20/ Feb 18 10:43:43: vmx| DICT pref.console.openedObj1.file = /vm/clones/ee7302d13a3ec0393327e5c5e5/master.vmx Feb 18 10:43:43: vmx| DICT pref.console.openedObj1.dest = /host2/#7f2f52b93ae2d99b/ Feb 18 10:43:43: vmx| DICT pref.console.currentObj.path = /vm/#37f7c916f078451f/ Feb 18 10:43:43: vmx| DICT pref.console.currentObj.type = vm Feb 18 10:43:43: vmx| DICT pref.placement.right = 957 Feb 18 10:43:43: vmx| DICT pref.placement.bottom = 628 Feb 18 10:43:43: vmx| DICT pref.console.openedObj2.present = TRUE Feb 18 10:43:43: vmx| DICT pref.console.openedObj2.type = vm Feb 18 10:43:43: vmx| DICT pref.console.openedObj2.path = /vm/#37f7c916f078451f/ Feb 18 10:43:43: vmx| DICT pref.console.openedObj2.file = /vm/firewall-3/honeywall.vmx Feb 18 10:43:43: vmx| DICT pref.console.openedObj2.dest = /host2/#7f2f52b93ae2d99b/ Feb 18 10:43:43: vmx| DICT pref.placement.left = 10 Feb 18 10:43:43: vmx| DICT pref.placement.top = 72 Feb 18 10:43:43: vmx| DICT --- USER DEFAULTS Feb 18 10:43:43: vmx| DICT --- HOST DEFAULTS Feb 18 10:43:43: vmx| DICT vmnet1.hostonlyaddress = 10.0.0.1 Feb 18 10:43:43: vmx| DICT serverd.init.fullpath = /usr/lib/vmware/serverd/init.pl Feb 18 10:43:43: vmx| DICT authd.client.port = 902 Feb 18 10:43:43: vmx| DICT control.fullpath = /usr/bin/vmware-cmd Feb 18 10:43:43: vmx| DICT authd.fullpath = /usr/sbin/vmware-authd Feb 18 10:43:43: vmx| DICT loop.fullpath = /usr/bin/vmware-loop Feb 18 10:43:43: vmx| DICT libdir = /usr/lib/vmware Feb 18 10:43:43: vmx| DICT vmware.fullpath = /usr/bin/vmware Feb 18 10:43:43: vmx| DICT vmnet1.hostonlynetmask = 255.255.255.0 Feb 18 10:43:43: vmx| DICT vmdir = /vm Feb 18 10:43:43: vmx| DICT dhcpd.fullpath = /usr/bin/vmnet-dhcpd Feb 18 10:43:43: vmx| DICT serverd.fullpath = /usr/sbin/vmware-serverd Feb 18 10:43:43: vmx| DICT datastore.name = local Feb 18 10:43:43: vmx| DICT datastore.localpath = /vm/ Feb 18 10:43:43: vmx| DICT --- SITE DEFAULTS Feb 18 10:43:43: vmx| DICT tag.help = introduction.htm Feb 18 10:43:43: vmx| DICT tag.configurationEditor = config_editor_newvm.htm Feb 18 10:43:43: vmx| DICT tag.ideConfig = devices_virtualdrive.htm Feb 18 10:43:43: vmx| DICT tag.floppyConfig = devices_floppy.htm Feb 18 10:43:43: vmx| DICT tag.mouseConfig = devices_mouse.htm Feb 18 10:43:43: vmx| DICT tag.netConfig = devices_netadapter.htm Feb 18 10:43:43: vmx| DICT tag.parallelConfig = devices_parallel.htm Feb 18 10:43:43: vmx| DICT tag.serialConfig = devices_serial.htm Feb 18 10:43:43: vmx| DICT tag.soundConfig = devices_sound.htm Feb 18 10:43:43: vmx| DICT tag.memConfig = configvm_memory.htm Feb 18 10:43:43: vmx| DICT tag.miscConfig = configvm.htm Feb 18 10:43:43: vmx| DICT tag.usbConfig = devices_usb.htm Feb 18 10:43:43: vmx| DICT tag.displayConfig = configvm_display-problems.htm Feb 18 10:43:43: vmx| DICT tag.tools = vmtools.htm Feb 18 10:43:43: vmx| DICT --- COMMAND LINE Feb 18 10:43:43: vmx| DICT gui.managementUI = TRUE Feb 18 10:43:43: vmx| DICT --- CONFIGURATION Feb 18 10:43:43: vmx| DICT config.version = 7 Feb 18 10:43:43: vmx| DICT virtualHW.version = 4 Feb 18 10:43:43: vmx| DICT scsi0.present = TRUE Feb 18 10:43:43: vmx| DICT memsize = 384 Feb 18 10:43:43: vmx| DICT ide0:0.present = TRUE Feb 18 10:43:43: vmx| DICT ide0:0.fileName = /vm/master/master.vmdk Feb 18 10:43:43: vmx| DICT ide0:0.writeThrough = TRUE Feb 18 10:43:43: vmx| DICT ide0:0.mode = independent-persistent Feb 18 10:43:43: vmx| DICT ide1:0.present = TRUE Feb 18 10:43:43: vmx| DICT ide1:0.fileName = /home/ablum/KNOPPIX_V5.1.1CD-2007-01-04-EN.iso Feb 18 10:43:43: vmx| DICT ide1:0.deviceType = cdrom-image Feb 18 10:43:43: vmx| DICT floppy0.fileName = /dev/fd0 Feb 18 10:43:43: vmx| DICT Ethernet0.present = TRUE Feb 18 10:43:43: vmx| DICT Ethernet0.connectionType = hostonly Feb 18 10:43:43: vmx| DICT displayName = da58eb1b2725f3f4e4181e182a Feb 18 10:43:43: vmx| DICT guestOS = winxppro Feb 18 10:43:43: vmx| DICT priority.grabbed = normal Feb 18 10:43:43: vmx| DICT priority.ungrabbed = normal Feb 18 10:43:43: vmx| DICT powerType.powerOff = hard Feb 18 10:43:43: vmx| DICT powerType.powerOn = hard Feb 18 10:43:43: vmx| DICT powerType.suspend = hard Feb 18 10:43:43: vmx| DICT powerType.reset = hard Feb 18 10:43:43: vmx| DICT floppy0.present = FALSE Feb 18 10:43:43: vmx| DICT ide0:0.redo = Feb 18 10:43:43: vmx| DICT ethernet0.addressType = generated Feb 18 10:43:43: vmx| DICT uuid.location = 56 4d 57 4d 5c 21 8c 83-8b f2 b0 2a f4 2a 35 3d Feb 18 10:43:43: vmx| DICT uuid.bios = 56 4d 57 4d 5c 21 8c 83-8b f2 b0 2a f4 2a 35 3d Feb 18 10:43:43: vmx| DICT ethernet0.generatedAddress = 00:0c:29:2a:35:3d Feb 18 10:43:43: vmx| DICT ethernet0.generatedAddressOffset = 0 Feb 18 10:43:43: vmx| DICT ide1:0.startConnected = FALSE Feb 18 10:43:43: vmx| DICT tools.syncTime = FALSE Feb 18 10:43:43: vmx| DICT ide0:0.deviceType = ata-hardDisk Feb 18 10:43:43: vmx| DICT --- USER DEFAULTS Feb 18 10:43:43: vmx| DICT --- HOST DEFAULTS Feb 18 10:43:43: vmx| DICT vmnet1.hostonlyaddress = 10.0.0.1 Feb 18 10:43:43: vmx| DICT serverd.init.fullpath = /usr/lib/vmware/serverd/init.pl Feb 18 10:43:43: vmx| DICT authd.client.port = 902 Feb 18 10:43:43: vmx| DICT control.fullpath = /usr/bin/vmware-cmd Feb 18 10:43:43: vmx| DICT authd.fullpath = /usr/sbin/vmware-authd Feb 18 10:43:43: vmx| DICT loop.fullpath = /usr/bin/vmware-loop Feb 18 10:43:43: vmx| DICT libdir = /usr/lib/vmware Feb 18 10:43:43: vmx| DICT vmware.fullpath = /usr/bin/vmware Feb 18 10:43:43: vmx| DICT vmnet1.hostonlynetmask = 255.255.255.0 Feb 18 10:43:43: vmx| DICT vmdir = /vm Feb 18 10:43:43: vmx| DICT dhcpd.fullpath = /usr/bin/vmnet-dhcpd Feb 18 10:43:43: vmx| DICT serverd.fullpath = /usr/sbin/vmware-serverd Feb 18 10:43:43: vmx| DICT datastore.name = local Feb 18 10:43:43: vmx| DICT datastore.localpath = /vm/ Feb 18 10:43:43: vmx| DICT --- SITE DEFAULTS Feb 18 10:43:43: vmx| DICT tag.help = introduction.htm Feb 18 10:43:43: vmx| DICT tag.configurationEditor = config_editor_newvm.htm Feb 18 10:43:43: vmx| DICT tag.ideConfig = devices_virtualdrive.htm Feb 18 10:43:43: vmx| DICT tag.floppyConfig = devices_floppy.htm Feb 18 10:43:43: vmx| DICT tag.mouseConfig = devices_mouse.htm Feb 18 10:43:43: vmx| DICT tag.netConfig = devices_netadapter.htm Feb 18 10:43:43: vmx| DICT tag.parallelConfig = devices_parallel.htm Feb 18 10:43:43: vmx| DICT tag.serialConfig = devices_serial.htm Feb 18 10:43:43: vmx| DICT tag.soundConfig = devices_sound.htm Feb 18 10:43:43: vmx| DICT tag.memConfig = configvm_memory.htm Feb 18 10:43:43: vmx| DICT tag.miscConfig = configvm.htm Feb 18 10:43:43: vmx| DICT tag.usbConfig = devices_usb.htm Feb 18 10:43:43: vmx| DICT tag.displayConfig = configvm_display-problems.htm Feb 18 10:43:43: vmx| DICT tag.tools = vmtools.htm Feb 18 10:43:43: vmx| DICT --- GLOBAL SETTINGS Feb 18 10:43:43: vmx| Msg_Hint: msg.guestos.xp (not shown) Feb 18 10:43:43: vmx| Msg_Hint: msg.hostlinux.othervms (not shown) Feb 18 10:43:43: vmx| WSSCAN: reserved mem (in MB) min=32 max=3968 recommended=3968 Feb 18 10:43:43: vmx| hostMem=4064 maxAllowedAll=-1 maxAllowedVM=3600 Feb 18 10:43:43: vmx| totOverhead=16 Feb 18 10:43:43: vmx| WSSCAN: used rec mem (in MB) 3968 Feb 18 10:43:43: vmx| WSSCAN: Overhead 104689 paged 5791 nonpaged 4096 maxFBSize Feb 18 10:43:43: vmx| WSSCAN 2 15027 1015808 -1 1015808 -1 50 43043 Feb 18 10:43:43: vmx| LICENSE using: '/etc/vmware/license.vs.1.0-00' Feb 18 10:43:43: vmx| STATDECLGROUP stats Root "" null Feb 18 10:43:43: vmx| Host CPUID features: version 0x6f8 id1.edx 0xbfebfbff id1.ecx 0xe3bd id81.edx 0x20100000 id81.ecx 0x1 Feb 18 10:43:43: vmx| CPU.cpuFeatures = 0xb971ff37 Feb 18 10:43:43: vmx| CPUID after masking: version 0x6f8 id1.edx 0xfebfbff id1.ecx 0xa215 id81.edx 0x20100800 id81.ecx 0x1 id88.ecx 0x0 Feb 18 10:43:43: vmx| CPU.cpuFeatures = 0x9871ff33 Feb 18 10:43:43: vmx| APIC: Local APIC at 0xfee00000 Feb 18 10:43:43: vmx| KHZEstimate 2399718 Feb 18 10:43:43: vmx| MHZEstimate 2400 Feb 18 10:43:43: vmx| NumVCPUs 1 Feb 18 10:43:43: vmx| UUID: location-UUID is 56 4d 11 3b eb db 5e 4d-95 e6 94 e6 94 bb 03 79 Feb 18 10:43:43: vmx| UUID: canonical path is /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmx Feb 18 10:43:43: vmx| UUID: location-UUID is 56 4d 11 3b eb db 5e 4d-95 e6 94 e6 94 bb 03 79 Feb 18 10:43:43: vmx| Msg_Question: Feb 18 10:43:43: vmx| [msg.uuid.moved] The location of this virtual machine's configuration file has changed since it was last powered on. Feb 18 10:43:43: vmx| Feb 18 10:43:43: vmx| If the virtual machine has been copied, you should create a new unique identifier (UUID). If it has been moved, you should keep its old identifier. Feb 18 10:43:43: vmx| Feb 18 10:43:43: vmx| If you are not sure, create a new identifier. Feb 18 10:43:43: vmx| Feb 18 10:43:43: vmx| What do you want to do?---------------------------------------- Feb 18 10:43:43: vmx| Msg_Question: msg.uuid.moved reply=1 Feb 18 10:43:43: vmx| UUID: Writing uuid.bios 56 4d 11 3b eb db 5e 4d-95 e6 94 e6 94 bb 03 79 Feb 18 10:43:43: vmx| UUID: Writing uuid.location 56 4d 11 3b eb db 5e 4d-95 e6 94 e6 94 bb 03 79 Feb 18 10:43:43: vmx| MM: Using partialmap, 98304 pages AC 0 CE 1 TM 0 DOHU 0 Feb 18 10:43:43: vmx| UUID: canonical path is /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmx Feb 18 10:43:43: vmx| UUID: location-UUID is 56 4d 11 3b eb db 5e 4d-95 e6 94 e6 94 bb 03 79 Feb 18 10:43:43: vmx| MM: using fileName /vm/clones/da58eb1b2725f3f4e4181e182a/564d113b-ebdb-5e4d-95e6-94e694bb0379.vmem for paging Feb 18 10:43:43: vmx| Msg_Reset: Feb 18 10:43:43: vmx| ---------------------------------------- Feb 18 10:43:43: vmx| Opened paging file /vm/clones/da58eb1b2725f3f4e4181e182a/564d113b-ebdb-5e4d-95e6-94e694bb0379.vmem Feb 18 10:43:43: vmx| Mapped mainmem as pageable Feb 18 10:43:43: vmx| MStat: Creating Stat vm.cpuusage Feb 18 10:43:43: vmx| MStat: Creating Stat vm.ram Feb 18 10:43:43: vmx| MStat: Creating Stat vm.uptime Feb 18 10:43:43: vmx| Unable to find /vm/clones/da58eb1b2725f3f4e4181e182a/master.vmss. Setting vmState to NULL. Feb 18 10:43:43: vmx| DISK: OPEN ide0:0 '/vm/master/master.vmdk' independent-persistent R[(null)] Feb 18 10:43:43: vmx| DISKLIB-LINK : "/vm/master/master.vmdk" : failed to open (Insufficient permission to access file).
Feb 18 10:43:43: vmx| DISKLIB-CHAIN : "/vm/master/master.vmdk" : failed to open (Insufficient permission to access file). Feb 18 10:43:43: vmx| DISKLIB-LIB : Failed to open '/vm/master/master.vmdk' with flags 0x2a (Insufficient permission to access file). Feb 18 10:43:43: vmx| DISK: Cannot open disk "/vm/master/master.vmdk": Insufficient permission to access file (38). Feb 18 10:43:43: vmx| DISK: Failed to open disk '/vm/master/master.vmdk' : Insufficient permission to access file (38) 3023. Feb 18 10:43:43: vmx| Msg_Post: Error Feb 18 10:43:43: vmx| [msg.disk.noBackEnd] Cannot open the disk '/vm/master/master.vmdk' or one of the snapshot disks it depends on. Feb 18 10:43:43: vmx| [msg.disk.configureDiskError] Reason: Insufficient permission to access file.---------------------------------------- Feb 18 10:43:43: vmx| Accepted new connection at 115 for thread servercontrol (0x84d13dc) Feb 18 10:43:43: vmx| VUINewControlConnection: before slow ACL gunk (bug 63252). Feb 18 10:43:43: vmx| ACL_InitCapabilities: here 2 (bug 63252) Feb 18 10:43:43: vmx| VUINewControlConnection: after slow ACL gunk (bug 63252). Feb 18 10:43:43: vmx| VUI: A new VMControl client connected. Feb 18 10:43:43: vmx| IPC version negotiation version: VMX returning 2.1 to servercontrol Feb 18 10:43:43: vmx| IPC vmcontrol-temp version: VMX returning 11.4 to servercontrol that tried 11.4 Feb 18 10:43:44: vmx| VMX IPC closed the connection with thread control (0x84d1360) Feb 18 10:43:44: vmx| VMX: Remote VMControl client control disconnected unexpectedly. root@ubuntu:/vm/clones/da58eb1b2725f3f4e4181e182a# }}}

dkindlund commented 14 years ago

Author: kindlund Based on the log, it's definitely a permissions issue:

{{{ Feb 18 10:43:43: vmx| DISKLIB-LINK : "/vm/master/master.vmdk" : failed to open (Insufficient permission to access file).
Feb 18 10:43:43: vmx| DISKLIB-CHAIN : "/vm/master/master.vmdk" : failed to open (Insufficient permission to access file). Feb 18 10:43:43: vmx| DISKLIB-LIB : Failed to open '/vm/master/master.vmdk' with flags 0x2a (Insufficient permission to access file). Feb 18 10:43:43: vmx| DISK: Cannot open disk "/vm/master/master.vmdk": Insufficient permission to access file (38). Feb 18 10:43:43: vmx| DISK: Failed to open disk '/vm/master/master.vmdk' : Insufficient permission to access file (38) 3023. Feb 18 10:43:43: vmx| Msg_Post: Error Feb 18 10:43:43: vmx| [msg.disk.noBackEnd] Cannot open the disk '/vm/master/master.vmdk' or one of the snapshot disks it depends on. Feb 18 10:43:43: vmx| [msg.disk.configureDiskError] Reason: Insufficient permission to access file.---------------------------------------- }}}

Okay, so to be clear, the master VM and the clone VM has the same ownership -- right? If not, be sure both are owned by the same user/group.

Lastly, when you reset and test again, try doing a 'chmod -R 777' on the master VM directory. When the StartManager.pl code runs, it will change the permissions of the files in the master VM directory accordingly (which is normal).

If that doesn't work, do an 'ls -alF' on the contents of the master VM directory and the subsequent clone VM directory and paste the output to this ticket. That will help me troubleshoot further.

-- Darien

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Same permissions issue as before:

For refence, on this system, the user account for everything honeyclient related is 'user'.

ls -alF of /vm/master {{{ root@ubuntu:/vm# cd /vm/master/ root@ubuntu:/vm/master# ls -alF total 2685488 drwxrwxrwx 2 user user 4096 2009-02-18 11:57 ./ drwxrwxrwt 6 user user 4096 2009-02-17 17:06 ../ -rwxrwxrwx 1 user user 61693952 2009-02-16 11:58 core -r--r----- 1 user user 1671954432 2009-02-18 10:57 master-s001.vmdk -r--r----- 1 user user 1065811968 2009-02-18 10:57 master-s002.vmdk -r--r----- 1 user user 65536 2009-02-18 10:57 master-s003.vmdk -r--r----- 1 user user 420 2009-02-18 10:56 master.vmdk -r--r----- 1 user user 0 2009-02-12 12:44 master.vmsd -rwxrwxrwx 1 user user 1058 2009-02-18 11:57 master.vmx -rwxrwxrwx 1 user user 8664 2009-02-16 19:38 nvram -rw-r--r-- 1 user user 3912 2009-02-18 11:57 vmware-0.log -rw-r--r-- 1 user user 3912 2009-02-18 11:57 vmware-1.log -rwxrwxrwx 1 user user 3912 2009-02-18 11:52 vmware-2.log -rw-r--r-- 1 user user 3912 2009-02-18 11:57 vmware.log }}}

ls -alF of /vm/clones/365ae80a27a73f034b0f7b1933 {{{ root@ubuntu:/vm/master# cd /vm/clones/365ae80a27a73f034b0f7b1933 root@ubuntu:/vm/clones/365ae80a27a73f034b0f7b1933# ls -alF total 56 drwxrwx--- 2 user user 4096 2009-02-18 11:57 ./ drwxrwx--- 3 user user 4096 2009-02-18 11:57 ../ -rw------- 1 user user 402653184 2009-02-18 11:57 564dadc2-2ecf-95db-4ba9-2c81c90b72b4.vmem -r--r--r-- 1 user user 11 2009-02-18 11:57 564dadc2-2ecf-95db-4ba9-2c81c90b72b4.vmem.WRITELOCK -rw------- 1 user user 0 2009-02-18 11:57 master.vmsd -rwxrwx--- 1 user user 1078 2009-02-18 11:57 master.vmx* -rw-r--r-- 1 user user 4177 2009-02-18 11:57 vmware-0.log -rw-r--r-- 1 user user 19225 2009-02-18 11:57 vmware.log root@ubuntu:/vm/clones/365ae80a27a73f034b0f7b1933# }}}

It's also noteworthy if I do a chmod -R 777 on both the master and the clone VM directorys after resolving the VMware question and unsticking the machine, the clone comes up via a "vmware-cmd /vm/clone//master.vmx start"

dkindlund commented 14 years ago

Author: kindlund Any chance you could upload a copy of these two files:

/vm/clones/365ae80a27a73f034b0f7b1933/master.vmx (call this 'clone.vmx') /vm/master/master.vmx

Specifically, I'm looking for the values of config.version and the hardware config versions.

-- Darien

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Oooh typo in master.vmx: config version was set to 7 but virtualHW version was set to 4.

I rectified this, 'answered' the old clone, unregistered it, reset permissions on the /vm/master directory restarted the vmware server then re-ran perl -Ilib bin/StartManager.pl

Same error :( {{{ user@ubuntu:~/honeyclient$ vmware-cmd /vm/clones/06465947f34643f0d6e82be81d/master.vmx answer

Question (id = 538622583) :Cannot open the disk '/vm/master/master.vmdk' or one of the snapshot disks it depends on. Reason: Insufficient permission to access file. 0) OK Select choice. Press enter for default <0> : 0 selected 0 : OK user@ubuntu:~/honeyclient$ }}}

Files follow:

Master: {{{

!/usr/bin/vmware

config.version = "7" virtualHW.version = "3" scsi0.present = "TRUE" memsize = "384" ide0:0.present = "TRUE" ide0:0.fileName = "/vm/master/master.vmdk" ide0:0.writeThrough = "TRUE" ide0:0.mode = "independent-persistent" ide1:0.present = "TRUE" ide1:0.fileName = "/home/ablum/KNOPPIX_V5.1.1CD-2007-01-04-EN.iso" ide1:0.deviceType = "cdrom-image" floppy0.fileName = "/dev/fd0" Ethernet0.present = "TRUE" Ethernet0.connectionType = "hostonly" displayName = "master" guestOS = "winxppro" priority.grabbed = "normal" priority.ungrabbed = "normal" powerType.powerOff = "hard" powerType.powerOn = "hard" powerType.suspend = "hard" powerType.reset = "hard"

floppy0.present = "FALSE"

ide0:0.redo = "" ethernet0.addressType = "generated" uuid.location = "56 4d 57 4d 5c 21 8c 83-8b f2 b0 2a f4 2a 35 3d" uuid.bios = "56 4d 57 4d 5c 21 8c 83-8b f2 b0 2a f4 2a 35 3d" ethernet0.generatedAddress = "00:0c:29:2a:35:3d" ethernet0.generatedAddressOffset = "0"

ide1:0.startConnected = "FALSE"

tools.syncTime = "FALSE"

ide0:0.deviceType = "ata-hardDisk" }}}

Clone: {{{ config.version = "7" virtualHW.version = "4" scsi0.present = "TRUE" memsize = "384" ide0:0.present = "TRUE" ide0:0.fileName = "/vm/master/master.vmdk" ide0:0.writeThrough = "TRUE" ide0:0.mode = "independent-persistent" ide1:0.present = "TRUE" ide1:0.fileName = "/home/ablum/KNOPPIX_V5.1.1CD-2007-01-04-EN.iso" ide1:0.deviceType = "cdrom-image" floppy0.fileName = "/dev/fd0" Ethernet0.present = "TRUE" Ethernet0.connectionType = "hostonly" displayName = "06465947f34643f0d6e82be81d" guestOS = "winxppro" priority.grabbed = "normal" priority.ungrabbed = "normal" powerType.powerOff = "hard" powerType.powerOn = "hard" powerType.suspend = "hard" powerType.reset = "hard"

floppy0.present = "FALSE"

ide0:0.redo = "" ethernet0.addressType = "generated" uuid.location = "56 4d a5 5b 32 42 27 bc-58 47 0a c8 e2 ae 28 73" uuid.bios = "56 4d a5 5b 32 42 27 bc-58 47 0a c8 e2 ae 28 73" ethernet0.generatedAddress = "00:0c:29:2a:35:3d" ethernet0.generatedAddressOffset = "0"

ide1:0.startConnected = "FALSE"

tools.syncTime = "FALSE"

ide0:0.deviceType = "ata-hardDisk" }}}

Not sure why but the clone seems to be getting a different hardware config version at this point, is there something else I need to reset?

dkindlund commented 14 years ago

Author: kindlund Hrm... What version of VMware Server are you using?

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Here's what the vmware server tells me: {{{ root@ubuntu:/vm/clones# vmware -v VMware Server 1.0.8 build-126538 }}}

dkindlund commented 14 years ago

Author: kindlund Okay, when you're modifying the master VM's disk settings, don't use the GUI.

Specifically, load up an editor and change this line on the master.vmx file:

{{{ ide0:0.mode = "independent-persistent" }}}

to read:

{{{ ide0:0.mode = "persistent" }}}

There is a difference between these two settings.

Unregister the clone, delete it, and re-try StartManager.pl. If it doesn't work, paste the error message.

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Thanks!

It seems like the clone is now being created successfully and powering up. Unfortuanately I think I've got something else wrong as the clients upon boot and start the agent repeatedly display {{{ FIREWALL STATUS = DISABLED. Waiting for firewall to allow network connectivity to this VM. }}}

Driving my browser to "http://127.0.0.1:3000/data/add_url" on the host system results in an error page "Action Controller: Exception Caught" {{{ Errno::ECONNREFUSED in DataController#add_url

Connection refused - connect(2) }}}

Is this related or have a screwed up somewhere else?

Thanks much,

Aaron

dkindlund commented 14 years ago

Author: kindlund Umm, okay, on your Master VM, what's the 'svn info' on this? I suspect your Agent codebase is synced with the trunk instead of v1.0.2, which is why it's not working. It's possible that there is a lingering 'svn update' call in the bin/bootstrap_agent.sh script. In this case, downgrade back to v1.0.2, then edit the bin/bootstrap_agent.sh file inside the master VM to disable 'svn update'.

Additionally, the http://127.0.0.1:300/data/add_url link you mentioned, assumes that you have the Drone ruby/rails webservice up and running -- is this correct? I assume you're also using v1.0.2 of the Drone code have it setup correct... is that correct?

-- Darien

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com I believe I am running trunk release on both Master and Host systems, I'll work on downgrading both.

Regarding the ruby webservice, I have the "ruby script/server -e production &" call running, were it not, I would not have anything listening on port 3000.

I believe I am running the v1.0.2 of the Drone code however.

I'll let you know what I come up with after the downgrades.

Thanks,

Aaron

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Actually, I'm running trunk release of the Drone code too, the only thing that is not trunk at this time is the firewall - would it be easier to upgrade the firewall VM than downgrade everything else?

dkindlund commented 14 years ago

Author: kindlund You should use v1.0.2 for everything. Either obtain the corresponding .tar.gz packages from the downloads section or use the path:

http://www.honeyclient.org/trac/browser/honeyclient/tags/rel/1.0.2

Couple of big points:

We've held off releasing packaged updates because the trunk codebase is undergoing significant architectural changes.

-- Darien

dkindlund commented 14 years ago

Author: Aaron aaron.blum@gmail.com Ok, thanks for the info. I'll push everything back to 1.0.2 - I think my question for this particular ticket has been answered.

Thanks for your time and patience.

Aaron

dkindlund commented 14 years ago

Author: Aaron Problem does not exist in 1.0.2 code base.