VM Compromised Reported on every site.....StartManager failing after snapshot

[dkindlund]

Hello,

For the past week I've been working towards completing a functional honeyclient for research purposes. When executing start manager to troll selected URLs...every URL is reporting a VM compromise. These are random site but known good sites (Hotmail, Google, CNN, and my own test site. I'm not use how to address this issue as I have tried what was reported in #180 which doesn't work for me.

The added issue is StartManager is killed after the subsequent snapshot of the 'compromised' VM is copied and another clone is being launched. I suspect the first issue plays a hand in the latter but I'm not sure. Below is the output of what I see during the report. Thanks in advance.

{{{
root@bishop:/home/ralph/honeyclient# perl -Ilib bin/StartManager.plStarting new session...
2009-10-08 12:24:56 INFO HoneyClient::Manager::VM::init - Initializing VM daemon at PID: 6977
2009-10-08 12:24:56 INFO HoneyClient::Manager::VM::Clone::new - Setting VM (/vm/master/master.vmx) as master.
2009-10-08 12:25:09 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.vmx).
2009-10-08 12:26:00 INFO HoneyClient::Manager::VM::Clone::_init - Initialized clone VM (5ef32a23cad9915e93e8b23739) using IP (10.0.0.128) and MAC (00:0c:29:2a:e0:e5).
hostname: Unknown host
VM State Table:
$VAR1 = {
'5ef32a23cad9915e93e8b23739' => {
'sources' => {
'00:0c:29:2a:e0:e5' => {
'10.0.0.128' => {
'tcp' => [
80,
443
]
}
}
}
}
};

Cannot encode unnamed element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'sources' element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'value' element as 'hash'. Will be encoded as 'map' instead
2009-10-08 12:26:40 INFO HoneyClient::Manager::get_urls - Waiting for new URLs from database.
Calling updateState()...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 0,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
VM Integrity Check: OK!
Cannot encode unnamed element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'sources' element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'value' element as 'hash'. Will be encoded as 'map' instead
VM State Table:
$VAR1 = {
'5ef32a23cad9915e93e8b23739' => {
'targets' => {
'www.cnn.com' => {
'tcp' => [
80
]
}
},
'sources' => {
'00:0c:29:2a:e0:e5' => {
'10.0.0.128' => {
'tcp' => [
80,
443
]
}
}
}
}
};

Cannot encode unnamed element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'sources' element as 'hash'. Will be encoded as 'map' instead
Cannot encode 'value' element as 'hash'. Will be encoded as 'map' instead
Calling run()...
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 6,
'is_running' => 1,
'links_processed' => 0,
'percent_complete' => '0.00%',
'is_compromised' => 0,
'relative_links_remaining' => 1,
'links_total' => 6
};
Sleeping for 2s...
Calling getStatus()...
Result:
$VAR1 = {
'links_remaining' => 5,
'is_running' => 0,
'links_processed' => 1,
'percent_complete' => '16.67%',
'is_compromised' => 1,
'relative_links_remaining' => 1,
'links_total' => 6,
'fingerprint' => {
'last_resource' => 'http://www.cnn.com/',
'time_at' => '2009-10-08 12:26:28.745',
'os_processes' => [
{
'stopped' => '2009-10-08 12:26:36.839',
'pid' => '1968',
'regkeys' => [],
'name' => 'C:\WINDOWS\system32\imapi.exe',
'process_files' => [
{
'name' => 'C:\WINDOWS\Temp\kr4dmxsh.TMP',
'file_content' => {
'sha1' => 'C:\WINDOWS\Temp\kr4dmxsh.TMP2009-10-08 12:26:28.745',
'md5' => 'C:\WINDOWS\Temp\kr4dmxsh.TMP2009-10-08 12:26:28.745',
'size' => -1,
'mime_type' => 'UNKNOWN'
},
'event' => 'Write',
'time_at' => '2009-10-08 12:26:28.745'
}
]
},
{
'created' => '2009-10-08 12:26:29.964',
'pid' => '548',
'parent_name' => 'C:\WINDOWS\system32\svchost.exe',
'regkeys' => [],
'name' => 'C:\WINDOWS\system32\wscntfy.exe',
'parent_pid' => '1036',
'process_files' => []
}
]
}
};
WARNING: VM HAS BEEN COMPROMISED!
2009-10-08 12:27:13 WARN HoneyClient::Manager::runSession - VM Compromised. Last Resource (http://www.cnn.com/)
2009-10-08 12:27:13 INFO HoneyClient::Manager::runSession - Saving fingerprint to 'fingerprint.dump'.
2009-10-08 12:27:13 INFO HoneyClient::Manager::runSession - Archiving VM...
2009-10-08 12:27:35 INFO HoneyClient::Manager::VM::snapshotVM - Snapshotting VM (/vm/clones/5ef32a23cad9915e93e8b23739/master.vmx) to (/vm/snapshots/5ef32a23cad9915e93e8b23739-20091008T122735.tar.gz).
2009-10-08 12:27:36 INFO HoneyClient::Manager::runSession - Saving URL History to Database.
2009-10-08 12:27:36 INFO HoneyClient::Manager::insert_url_history - 1 URL(s) Inserted.
2009-10-08 12:27:36 INFO HoneyClient::Manager::runSession - Inserting Fingerprint Into Database.
2009-10-08 12:27:36 INFO HoneyClient::Manager::runSession - Database Insert Successful.
Starting new session...
2009-10-08 12:27:37 INFO HoneyClient::Manager::VM::Clone::new - Setting VM (/vm/master/master.vmx) as master.
2009-10-08 12:27:54 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.vmx).
/bin/tar: 5ef32a23cad9915e93e8b23739/master.vmem: file changed as we read it
2009-10-08 12:28:02 WARN HoneyClient::Manager::VM::ANON - Could not snapshot VM to (/vm/snapshots/5ef32a23cad9915e93e8b23739-20091008T122735.tar.gz). (256: )
2009-10-08 12:28:02 ERROR HoneyClient::Util::SOAP::_handleFault - Error occurred during processing. HoneyClient::Manager::VM->snapshotVM(): Could not snapshot VM to (/vm/snapshots/5ef32a23cad9915e93e8b23739-20091008T122735.tar.gz).
HoneyClient::Manager::VM->snapshotVM(): {'err' => bless( {'errNo' => '256','errStr' => ''}, 'err' )}
HoneyClient::Util::SOAP->handleFault(): Error occurred during processing.
HoneyClient::Manager::VM->snapshotVM(): Could not snapshot VM to (/vm/snapshots/5ef32a23cad9915e93e8b23739-20091008T122735.tar.gz).
HoneyClient::Manager::VM->snapshotVM(): {'err' => bless( {'errNo' => '256','errStr' => ''}, 'err' )}
Killed
}}}

[dkindlund]

Author: andrehall815@gmail.com
If there's anything else you need to know please let me know

[dkindlund]

Author: kindlund
Okay, just as you suspected, there are two problems with your setup:

1. It looks like you need to update your .exl files to reflect the consistent false positives that Capture-HPC is reporting; this is detailed extensively in ticket VM Compromised with all sites visited #180.
2. More importantly, it looks like the 'quick clone' operation is failing, as described in this error:

{{{
2009-10-08 12:27:54 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.vmx).
/bin/tar: 5ef32a23cad9915e93e8b23739/master.vmem: file changed as we read it
}}}

There is a problem with your master.vmx configuration; see this ticket for more information:

http://www.honeyclient.org/trac/ticket/148#comment:9

Specifically, your master.vmx should only have this as the ide0:0.mode:
{{{
ide0:0.mode = "persistent"
}}}

[dkindlund]

Author: andrehall815@gmail.com
Hi,

I had already done some sleuthing around before I had discovered Ticket 148 as I'm trying to document issues I encounter as I go along. I had gone into the master.vmdk setting the required value to '3' instead of '4'. I also checked to ensure the values in master.vmx were identical to what the documentation recommended. What I do notice is when I set the ide:0.mode to "persisent" it changes to "undoable" after I start StartManager.pl. Is this normal. In following along Ticket #148 the user continued to have errors as I do and you suggested changing master.vmx to master.cfg. I've done this but my honeyclient appears to be in a coma. I have the honeywall and drone started but when I run StartManager it's created the clone but IE is not being driven to the URLs in the drone database. Its been sitting idle for close to 30 minutes now. Any suggestions?

[dkindlund]

Author: kindlund
Hi Andre,

Can you paste the log associated with StartManager.pl? Also, can you please attach your master.vmx configuration file to this ticket? Lastly, please paste the cloned .vmx configuration file, once the cloned VM is created.

[dkindlund]

Author: andrehall815@gmail.com
Here is the output of StartManager.pl:

root@bishop:/home/ralph/honeyclient# perl -Ilib bin/StartManager.pl
Starting new session...
2009-10-16 11:09:23 INFO HoneyClient::Manager::VM::init - Initializing VM daemon at PID: 8419
2009-10-16 11:09:23 INFO HoneyClient::Manager::VM::Clone::new - Setting VM (/vm/master/master.cfg) as master.
2009-10-16 11:09:37 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.cfg).

Terminal activity is idle and there's no activity in the VM.

The master.vmx file attached represents the state the configuration was in before I renamed the file to master.cfg

The master.cfg file attached is the file from the clone directory. This is the state of the file once the clone is created and started.

I changed my the configuration back to its original setting (set honeyclient.xml to set master.vmx instead of master.cfg) and changing back doesn't seem to help.

To give you a bit more information. I'm using VMWare 1.0.9/Ubuntu 7.10 running on an system with an AMD 2.4GHz Athlon 64 X2, I have 2GB of memory and a 4GB swap file.

I'm really not sure what's happening since the only change I've made today was copying master.vmx to master.cfg. Any idea what's going on?

[dkindlund]

Author: andrehall815@gmail.com
Something else I've noticed. The master VM'x master.vmx ide mode changes from "persistent" to "undoable" after the clone is created. Is this normal?

[dkindlund]

Author: Stefan
Replying to [comment:6 andrehall815@gmail.com]:

Something else I've noticed. The master VM'x master.vmx ide mode changes from "persistent" to "undoable" after the clone is created. Is this normal?

Hi, I have the same behaviour. ide mode changes from "persistent" to "undoable" as I start StartManager.pl. No sites get actually visited.

[dkindlund]

Author: kindlund
Hi Andre & Stefan:

Okay, the change from "persistent" to "undoable" is normal and expected. After checking your master.vmx file further, Andre, can you please remove the following line and re-run StartManager.pl:

{{{
uuid.action = "keep"
}}}

The problem is that this line tells VMware Server to NOT generate a new, unique MAC address for the clone VM -- this can be a problem if you start multiple clones simultaneously.

Additionally, Andre, you indicated that the code stops at this line:

{{{
2009-10-16 11:09:37 INFO HoneyClient::Manager::VM::Clone::_init - Quick cloning master VM (/vm/master/master.cfg).
}}}

What are the specifications of your host system? Do you have at least a 2Ghz CPU? Also, do you have 2GB of RAM? Lastly, when the process is hanging at this line, can you indicate what your CPU load is when this occurs?

If there's little to no CPU utilization, then it looks like your threading libraries may need to be updated via CPAN. Specifically, try running the following commands to update your threading libraries as ROOT:

{{{

cpan

install threads
install threads::shared
install Thread::Queue
install Thread::Semaphore
}}}

... once you've updated these libraries, run StartManager.pl and let me know if the status output is any different.

Thanks,
Darien