Invoke-VMScript Failed - and how I was Baffled.

Luc Dekens wrote a great post a while back Will Invoke-VMScript work? about the prerequisites needed in order to get Invoke-VMscript to work. Stop for a minute and go and read his post.

Glad to have back.

As part of an Oracle RAC provisioning script that I am working on – one of the first things I wanted to do was to configure the network settings for my two nodes – with parameters taken from a config file.

Of course if the VM does not have an IP address yet then you cannot configure it through the network, so here is where Invoke-VMscript comes into play.

A few things first off the bat. My configuration was working also with the 32-bit engine but also with the 64-bit engine as well. The rest of the prerequisites were all there.

So here is what was happening. In the script I had stored the HostCredentials and the Guestcredentials each in a variable. When it came time power on the VM’s,The script would wait for the VMware tools to start running in the guest before executing the command and then run my script inside the guest OS – but the command would fail with this message.

Invoke-VMScript : 02/01/2013 15:17:07    Invoke-VMScript        Error occured while executing script on guest OS in VM
'testdbCA1b'. Could not locate "Powershell" script interpreter in any of the expected locations. Probably you do not have enough permissions to execute command within guest.
At line:5 char:1
+ Invoke-VMScript -ScriptText $bb -vm $dbvm2 -HostCredential $hostcreds -GuestCred ...
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : ResourceUnavailable: (testdbCA1b:VirtualMachineImpl) [Invoke-VMScript], VimException
    + FullyQualifiedErrorId : Client20_VmGuestServiceImpl_RunScriptCore_ExeLookupFailed,VMware.VimAutomation.ViCore.Cmdlets.Commands.InvokeVmScript

Now this was really weird – because this was completely not true. To make it even more baffling – when trying to run the commands manually – not as part of the script – it would work – without a problem. So I was starting to think that perhaps there was a problem that the credentials were not being passed properly down to the command – which was not likely – but still I had no other clue.

I then wondered – Invoke-VMscript – interacts with the VMware Tools in the guest through VIX – so maybe there was a problem there.

So I checked my versions (it was 1.12) and looked at the release notes and saw something there that ultimately led me onto the right path.

OK I was not getting any of these errors, but my command would not work. So I wanted to see what the logs of the VMware Tools in the guest were saying – after all it was interacting with the guest through VMware Tools. But where was the log?

KB1007873 - Enabling debug logging for VMware Tools within a guest operating system showed me the way to enable VMware Tools logging in a Linux VM.

You need to create a file (if it does not exist) /etc/vmware-tools/tools.conf and add to that file:

log = true
log.file = /tmp/vmtools.log

I then performed the following to test my theory.

Restart the VM
Wait for the tools to report Running and up-to-date
Invoke-VMscript

This I did with a simple PowerShell script.

Restart-VM -VM $dbvm2 -Confirm :$false
Sleep 10
while (((get-vm $dbvm2 ).ExtensionData.Guest.ToolsRunningStatus ) -ne "guestToolsRunning" ) {
Write-Host "....." -ForegroundColor Yellow
Sleep 5
}

Invoke-VMScript -ScriptText $bb -vm $dbvm2 -HostCredential $hostcreds -GuestCredential $guestcreds
while ( $? -eq $false ) {
Get-Date -Format HH :mm :ss
sleep 2
Invoke-VMScript -ScriptText $bb -vm $dbvm2 -HostCredential $hostcreds -GuestCredential $guestcreds
}

So I noticed a few things.

VMware Tools comes up and reports itself as running – way before the OS is actually available – and that you have a console prompt.
Even before SSH starts
The first 3-5 tries of Invoke-VMscript would fail – with the same error message I had before. And suddenly it would work as if nothing was wrong.

I went to look in the VMware Tools log that I had just configured and there I found something which I find very strange – but did solve my mystery but I still do not have the answer as to why it is happening.

For the failed attempts I had this in the log.

[Jan 02 13:17:06.925] [ debug] [vix] VixTools_StartProgram: args: progamPath: 'cmd.exe', arguments: '/C powershell -NonInteractive -EncodedCommand cABvAHcAZQByAHMAaABlAGwAbAAuAGUAeABlACAALQBPAHUAdABwAHUAdABGAG8AcgBtAGEAdAAgAHQAZQB4AHQAIAAtAE4AbwBuAEkAbgB0AGUAcgBhAGMAdABpAHYAZQAgAC0AQwBvAG0AbQBhAG4AZAAgACcAJgAgAHsAbABzACAALQBsAGEAfQAnACAAPgAgACIALwB0AG0AcAAvAHAAbwB3AGUAcgBjAGwAaQB2AG0AdwBhAHIAZQAwACIAOwAgAGUAeABpAHQAIAAkAGwAYQBzAHQAZQB4AGkAdABjAG8AZABlAA=='', workingDir: '

[Jan 02 13:17:11.988] [ debug] [vix] VixTools_StartProgram: args: progamPath: 'cmd.exe', arguments: '/C powershell -NonInteractive -EncodedCommand cABvAHcAZQByAHMAaABlAGwAbAAuAGUAeABlACAALQBPAHUAdABwAHUAdABGAG8AcgBtAGEAdAAgAHQAZQB4AHQAIAAtAE4AbwBuAEkAbgB0AGUAcgBhAGMAdABpAHYAZQAgAC0AQwBvAG0AbQBhAG4AZAAgACcAJgAgAHsAbABzACAALQBsAGEAfQAnACAAPgAgACIALwB0AG0AcAAvAHAAbwB3AGUAcgBjAGwAaQB2AG0AdwBhAHIAZQAwACIAOwAgAGUAeABpAHQAIAAkAGwAYQBzAHQAZQB4AGkAdABjAG8AZABlAA=='', workingDir: '

But for the successful attempt the log showed (which was what I expected)

[Jan 02 13:17:23.211] [   debug] [vix] VixTools_StartProgram: args: progamPath: '/bin/bash', arguments: '-c "bash > /tmp/powerclivmware0 2>&1 -c \"ls -la\""'', workingDir: '
[Jan 02 13:17:23.211] [   debug] [vmsvc] Executing async command: '"/bin/bash" -c "bash > /tmp/powerclivmware0 2>&1 -c \"ls -la\""' in working dir '/root'
[Jan 02 13:17:23.214] [   debug] [vix] VixToolsStartProgramImpl started '"/bin/bash" -c "bash > /tmp/powerclivmware0 2>&1 -c \"ls -la\""', pid 3792

Now here is the weird part. If you look at the first two failures – you will see that VIX trying to execute a Windows command on a Linux operating system – which…. probably .. won’t…. really…. work…. !!!

Only about 20 seconds later – did it execute the correct bash command – in my case ‘ls –la’ and it worked of course.

So here I found my way around my problem – but have not gotten to the bottom of the mystery yet. I put in an extra sleep statement into the script that would wait a bit longer until the OS was completely up and only then run the Invoke-VMscript command – and all was working fine…

So a few things I learned today:

How to enable logging for VMware Tools
VIX does weird things.
A workaround is as good of a solution as any other.
I would add one more thing to Luc’s prerequisites – wait until the VM has completely started before attempting to use Invoke-VMscript.

2013-01-02

Invoke-VMScript Failed - and how I was Baffled.