VMware Cloud Community
BenFB
Virtuoso
Virtuoso

Error when using Invoke-VMScript

We are trying to use Invoke-VMScript to configure a VM without network connectivity. 

When using Invoke-VMScript cmdlet we get the error "Could not locate "Powershell" script interpreter in any of the expected locations. Probably you do not have enough permissions to execute command within guest." 

We are using the local administrator account on the vm. We’ve tested running the same script on the VM, and it works.

Reply
0 Kudos
42 Replies
LucD
Leadership
Leadership

Can you share the Invoke-VMScript command you are using?

Which PowerCLI version are you using?

Did you check if there is anything in the vmware.log file?

You could also enable debugging for VMware Tools (see KB1007873), and check if that if that provides more info in the log.


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

Hi LucD,

I was hoping I would hear from you on this but I figured you would be at VMworld.

We are running VMware PowerCLI 11.3.0 build 13990089.

We tail vmware.log and this is all that's logged.
2019-08-27T19:20:32.078Z| vmx| I125: VigorTransportProcessClientPayload: opID=2bb59b0-1-5484 seq=408585: Receiving GuestOps.CreateTemporaryFile request.
2019-08-27T19:20:32.162Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=2bb59b0-1-5484 seq=408585: Completed GuestOps request.
2019-08-27T19:20:32.600Z| vmx| I125: VigorTransportProcessClientPayload: opID=606ada00-e6-548d seq=408600: Receiving GuestOps.DeleteFile request.
2019-08-27T19:20:32.664Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=606ada00-e6-548d seq=408600: Completed GuestOperations request.

Here is the script we are trying to run.

param(
    [parameter()]
    [System.String]
    $VM = "Test3",

    [parameter()]
    [System.String]
    $GuestUser = "sysop",

    [parameter(mandatory = $true)]
    [System.String]
    $GuestPassword
)

Set-StrictMode -Version Latest

$ErrorActionPreference = "Stop"

$GuestCredential = New-Object -TypeName System.Management.Automation.PSCredential -ArgumentList $GuestUser, ($GuestPassword | ConvertTo-SecureString -AsPlainText -Force)

$HostCredential = Get-Credential -Message "Host Credential"

Write-Host -ForegroundColor Green "Connecting to VIServer"
Connect-VIServer -server $VIServer -credential $HostCredential

$InvokeSettings = @{
    ScriptText      = "Get-ChildItem"
    VM              = $vm
    GuestCredential = $GuestCredential
    Server          = "$vCenter"
}

Invoke-VMScript @InvokeSettings

p
aram(
    [parameter()]
    [System.String]
    $VM = "Test3",
 
    [parameter()]
    [System.String]
    $GuestUser = "sysop",
 
    [parameter(mandatory = $true)]
    [System.String]
    $GuestPassword
)
 
Set-StrictMode -Version Latest
 
$ErrorActionPreference = "Stop"
 
$GuestCredential = New-Object -TypeName System.Management.Automation.PSCredential -ArgumentList $GuestUser, ($GuestPassword | ConvertTo-SecureString -AsPlainText -Force)
 
$HostCredential = Get-Credential -Message "Host Credential"
 
Write-Host -ForegroundColor Green "Connecting to VIServer"
Connect-VIServer -server $VIServer -credential $HostCredential
 
$InvokeSettings = @{
    ScriptText      = "Get-ChildItem"
    VM              = $vm
    GuestCredential = $GuestCredential
    Server          = "$vCenter"
}
 
Invoke-VMScript @InvokeSettings
Reply
0 Kudos
LucD
Leadership
Leadership

Are you sure that VM is running a Windows guest OS with powershell installed?

If it is a Linux guest OS, you will have to use ScriptType 'bash' and start pwsh in the code you send.

See something similar in Invoke-VMScript not working on Debian 9


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

The guest is Windows Server 2016 so PowerShell is present. If we login to the console of the VM we can run the same command, Get-ChildItem, with success.
Reply
0 Kudos
LucD
Leadership
Leadership

Can you try the following variation.

It waits till the GuestOperationsReady property says $true

param(

   [parameter()]

   [System.String]

   $VM = "Test3",

   [parameter()]

   [System.String]

   $GuestUser = "sysop",

   [parameter(mandatory = $true)]

   [System.String]

   $GuestPassword

)


Set-StrictMode -Version Latest

$ErrorActionPreference = "Stop"

$GuestCredential = New-Object -TypeName System.Management.Automation.PSCredential -ArgumentList $GuestUser, ($GuestPassword | ConvertTo-SecureString -AsPlainText -Force)

$HostCredential = Get-Credential -Message "Host Credential"

Write-Host -ForegroundColor Green "Connecting to VIServer"

Connect-VIServer -server $VIServer -credential $HostCredential

$vmObj = Get-VM -Name $VM

while (-not $vmObj.ExtensionData.Guest.GuestOperationsReady) {

  sleep 5

   $vmObj = Get-VM -Name $VM

}

$InvokeSettings = @{

   ScriptText = "Get-ChildItem"

   VM = $vmObj

   GuestCredential = $GuestCredential

   Server = "$vCenter"

}

Invoke-VMScript @InvokeSettings


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

We tried the suggestion but received the same result.

Checking the $vmObj.ExtensionData.Guest.GuestOperationsReady variable, it was already True, so the script skipped the wait loop.

Reply
0 Kudos
LucD
Leadership
Leadership

Did you enable VMware Tools debugging (the KB I linked to earlier)?

It might give some more info.


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

We enabled VMware Tools debugging and repeated the process. In vmsvc.log we found relevant entries to when the script was run. I've attached the log.
Reply
0 Kudos
LucD
Leadership
Leadership

Did you already try adding the -ScriptType PowerShell parameter to the Invoke-VMScript cmdlet?


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

It failed with this error.

Invoke-VMScript : 9/3/2019 12:01:38 PM  Invoke-VMScript         An error occurred while sending the request.
At line:1 char:1
+ Invoke-VMScript @InvokeSettings -ScriptType Powershell
+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Invoke-VMScript], ViError
    + FullyQualifiedErrorId : Client20_VmGuestServiceImpl_DownloadFileFromGuest_DownloadError,VMware.VimAutomation.ViCore.Cmdlets.Commands.InvokeVmScript

Reply
0 Kudos
LucD
Leadership
Leadership

Are you sure that port 902 between the guest OS in that VM and the ESXi node on which the VM is running is open?

That is the port used to communicate for the GuestOperations.
Perhaps try disabling the FW in the guest OS as a test.


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

We are automating our server build process and at the moment the VM has no network connectivity. We are trying to use Invoke-VMScript to configure the NIC to bring it online and continue the build.

Reply
0 Kudos
LucD
Leadership
Leadership

Sorry, I stated that incorrect, I meant port 902 between the station where you run Invoke-VMScript and the ESXi node where the VM is hosted.
The guest OS itself doesn't need network connectivity


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

I've verified that TCP/UDP 902 are open from the machine running Invoke-VMScript to the ESXi host where the guest resides that we are trying to interact with.

Reply
0 Kudos
LucD
Leadership
Leadership

That log you attached earlier, is that the vmware.log for that VM?


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

It's the VMware Tools vmsvc debug log from within the guest.

Reply
0 Kudos
LucD
Leadership
Leadership

Could also have a look, or attach, the vmware.log file.

You find that in the VM's folder on the datastore.


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos
BenFB
Virtuoso
Virtuoso

We ran the script while tail vmware.log and captured 4 lines.

vmware.log

2019-09-03T20:20:53.996Z| vmx| I125: VigorTransportProcessClientPayload: opID=730a5939-b1-fa24 seq=671536: Receiving GuestOps.CreateTemporaryFile request.

2019-09-03T20:20:54.125Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=730a5939-b1-fa24 seq=671536: Completed GuestOps request.

2019-09-03T20:20:54.382Z| vmx| I125: VigorTransportProcessClientPayload: opID=7663c460-b1-fa2d seq=671551: Receiving GuestOps.DeleteFile request.

2019-09-03T20:20:54.423Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=7663c460-b1-fa2d seq=671551: Completed GuestOperations request.

vmsvc.log

[Sep 03 14:20:38.850] [   debug] [vmsvc] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:40.716] [   debug] [vmsvc] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:20:40.716] [   debug] [vmsvc] RpcIn: sending 3 bytes

[Sep 03 14:20:43.904] [   debug] [vmsvc] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:47.700] [   debug] [vmsvc] RpcIn: received 152 bytes, content:"Vix_1_Relayed_Command "10c6cb9924e7f4ed"\00\01\00\0dÐ\05\00o\00\00\003\00\00\00\1f\00\00\00\1d\00\00\00\0dµ\00\00\00\00\01\00\00..."

[Sep 03 14:20:47.700] [ message] [vix] VixTools_ProcessVixCommand: command 181

[Sep 03 14:20:47.701] [   debug] [VCGA] VGAuth_CreateHandleForUsername: Created handle 0000000001DEE1D0

[Sep 03 14:20:47.727] [   debug] [VCGA] [function VGAuthLoadUserProfile, file d:/build/ob/bora-8059742/bora-vmsoft/vgauth/lib/impersonateWin32.c, line 123], Loaded profile for user 'sysop'

[Sep 03 14:20:47.727] [   debug] [vix] VixToolsImpersonateUser: successfully impersonated user sysop

[Sep 03 14:20:47.727] [   debug] [vix] VixToolsCreateTempFile: User: sysop

[Sep 03 14:20:47.727] [   debug] [vix] VixToolsCreateTempFile: returning 'C:\Users\sysop\AppData\Local\Temp\powerclivmware123'

[Sep 03 14:20:47.727] [   debug] [VCGA] [function VGAuthUnloadUserProfile, file d:/build/ob/bora-8059742/bora-vmsoft/vgauth/lib/impersonateWin32.c, line 156], Unloaded profile for user 'sysop'

[Sep 03 14:20:47.727] [   debug] [VCGA] VGAuth_UserHandleFree: Freed handle 0000000001DEE1D0

[Sep 03 14:20:47.727] [ message] [vix] VixToolsCreateTempFile: opcode 181 returning 0

[Sep 03 14:20:47.727] [   debug] [vix] ToolsDaemonTcloReceiveVixCommand: command 181, additionalError = 0

[Sep 03 14:20:47.727] [   debug] [vmsvc] RpcIn: sending 59 bytes

[Sep 03 14:20:48.025] [   debug] [vmsvc] RpcIn: received 181 bytes, content:"Vix_1_Relayed_Command "10c6cb9a1ae04501"\00\01\00\0dÐ\05\00Œ\00\00\003\00\00\00<\00\00\00\1d\00\00\00\05Â\00\00\00\00\01\00\00ÿÿ..."

[Sep 03 14:20:48.025] [ message] [vix] VixTools_ProcessVixCommand: command 194

[Sep 03 14:20:48.025] [   debug] [VCGA] VGAuth_CreateHandleForUsername: Created handle 0000000001DEE1D0

[Sep 03 14:20:48.025] [   debug] [VCGA] [function VGAuthLoadUserProfile, file d:/build/ob/bora-8059742/bora-vmsoft/vgauth/lib/impersonateWin32.c, line 123], Loaded profile for user 'sysop'

[Sep 03 14:20:48.025] [   debug] [vix] VixToolsImpersonateUser: successfully impersonated user sysop

[Sep 03 14:20:48.025] [   debug] [vix] VixToolsDeleteObject: User: sysop path: 'C:\Users\sysop\AppData\Local\Temp\powerclivmware123'

[Sep 03 14:20:48.025] [   debug] [VCGA] [function VGAuthUnloadUserProfile, file d:/build/ob/bora-8059742/bora-vmsoft/vgauth/lib/impersonateWin32.c, line 156], Unloaded profile for user 'sysop'

[Sep 03 14:20:48.025] [   debug] [VCGA] VGAuth_UserHandleFree: Freed handle 0000000001DEE1D0

[Sep 03 14:20:48.025] [ message] [vix] VixToolsDeleteObject: opcode 194 returning 0

[Sep 03 14:20:48.025] [   debug] [vix] ToolsDaemonTcloReceiveVixCommand: command 194, additionalError = 0

[Sep 03 14:20:48.025] [   debug] [vmsvc] RpcIn: sending 8 bytes

[Sep 03 14:20:49.000] [   debug] [vmsvc] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:50.452] [   debug] [guestinfo] Entered guest info stats poll.

[Sep 03 14:20:50.452] [   debug] [guestinfo] Exiting guest info stats poll: gather thread woken.

[Sep 03 14:20:50.452] [   debug] [guestinfo] GuestInfoStatProviderWorker: Stat worker refreshing

[Sep 03 14:20:50.484] [   debug] [guestinfo] GuestInfoStatProviderWorker: Stat worker serializing

[Sep 03 14:20:50.484] [   debug] [guestinfo] GuestInfoStatProviderWorker: Stat worker responding

[Sep 03 14:20:50.484] [   debug] [guestinfo] GuestInfoStatProviderWorker: Stat worker queuing response

[Sep 03 14:20:50.484] [   debug] [guestinfo] Entered guest info stats reporter.

[Sep 03 14:20:50.484] [   debug] [guestinfo] Entered update vmdb: 8.

[Sep 03 14:20:50.484] [   debug] [guestinfo] Sending GuestMemInfo message.

[Sep 03 14:20:50.484] [   debug] [vmsvc] RpcChannel: Sending: 322 bytes

[Sep 03 14:20:50.484] [   debug] [vmsvc] VSockChan: Sending request for conn 576,  reqLen=322

[Sep 03 14:20:50.484] [   debug] [vmsvc] SimpleSock: Sent 354 bytes from socket 576

[Sep 03 14:20:50.486] [   debug] [vmsvc] SimpleSock: Recved 4 bytes from socket 576

[Sep 03 14:20:50.486] [   debug] [vmsvc] SimpleSock: Recved 14 bytes from socket 576

[Sep 03 14:20:50.486] [   debug] [vmsvc] VSockOut: recved 2 bytes for conn 576

[Sep 03 14:20:50.486] [   debug] [vmsvc] RpcChannel: Recved 0 bytes

[Sep 03 14:20:50.486] [   debug] [guestinfo] GuestMemInfo sent successfully.

[Sep 03 14:20:50.486] [   debug] [guestinfo] Returning after updating guest information: 8

[Sep 03 14:20:50.486] [   debug] [guestinfo] Reported 0x00000132 stat bytes.

[Sep 03 14:20:50.486] [   debug] [guestinfo] Exiting guest info stats reporter.

vmusr.username.log

[Sep 03 14:20:33.324] [   debug] [vmusr] RpcChannel: Sending: 28 bytes

[Sep 03 14:20:33.324] [   debug] [vmusr] VSockChan: Sending request for conn 524,  reqLen=28

[Sep 03 14:20:33.324] [   debug] [vmusr] SimpleSock: Sent 60 bytes from socket 524

[Sep 03 14:20:33.324] [   debug] [vmusr] SimpleSock: Recved 4 bytes from socket 524

[Sep 03 14:20:33.324] [   debug] [vmusr] SimpleSock: Recved 15 bytes from socket 524

[Sep 03 14:20:33.324] [   debug] [vmusr] VSockOut: recved 3 bytes for conn 524

[Sep 03 14:20:33.324] [   debug] [vmusr] RpcChannel: Recved 1 bytes

[Sep 03 14:20:36.029] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:41.104] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:46.199] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:47.962] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:20:47.962] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:20:51.291] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:20:56.366] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:01.421] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:03.009] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:21:03.009] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:21:06.480] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:11.513] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:16.546] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:18.014] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:21:18.014] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:21:21.573] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:26.586] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:31.672] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:33.113] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:21:33.113] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:21:33.323] [   debug] [vmusr] RpcChannel: Sending: 28 bytes

[Sep 03 14:21:33.323] [   debug] [vmusr] VSockChan: Sending request for conn 524,  reqLen=28

[Sep 03 14:21:33.323] [   debug] [vmusr] SimpleSock: Sent 60 bytes from socket 524

[Sep 03 14:21:33.323] [   debug] [vmusr] SimpleSock: Recved 4 bytes from socket 524

[Sep 03 14:21:33.323] [   debug] [vmusr] SimpleSock: Recved 15 bytes from socket 524

[Sep 03 14:21:33.323] [   debug] [vmusr] VSockOut: recved 3 bytes for conn 524

[Sep 03 14:21:33.323] [   debug] [vmusr] RpcChannel: Recved 1 bytes

[Sep 03 14:21:36.694] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:41.743] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:46.813] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:48.150] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:21:48.150] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:21:51.847] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:21:56.948] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:22:02.044] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:22:03.182] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:22:03.182] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:22:07.166] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:22:12.226] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:22:17.311] [   debug] [vmusr] RpcIn: received 0 bytes, empty TCLO poll

[Sep 03 14:22:18.103] [   debug] [dndcp] PointerUpdatePointerLoop: grabbed

[Sep 03 14:22:18.212] [   debug] [vmusr] RpcIn: received 5 bytes, content:"ping\00"

[Sep 03 14:22:18.212] [   debug] [vmusr] RpcIn: sending 3 bytes

[Sep 03 14:22:18.509] [   debug] [dndcp] CopyPaste_GetBackdoorSelections: enter

[Sep 03 14:22:18.509] [   debug] [dndcp] CopyPaste_GetSelectionBD: get selection from host

[Sep 03 14:22:18.509] [   debug] [dndcp] CopyPaste_GetSelectionBD: Host selection len 579: [2019-09-03T20:20:53.996Z| vmx| I125: VigorTransportProcessClientPayload: opID=730a5939-b1-fa24 seq=671536: Receiving GuestOps.CreateTemporaryFile request.

2019-09-03T20:20:54.125Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=730a5939-b1-fa24 seq=671536: Completed GuestOps request.

2019-09-03T20:20:54.382Z| vmx| I125: VigorTransportProcessClientPayload: opID=7663c460-b1-fa2d seq=671551: Receiving GuestOps.DeleteFile request.

2019-09-03T20:20:54.423Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=7663c460-b1-fa2d seq=671551: Completed GuestOperations request.]

Reply
0 Kudos
LucD
Leadership
Leadership

The transfer of the files to/from the VM seems to be ok.

Could you try to run a batch script. Change ScriptType and ScriptText

-ScriptType Bat -ScriptText "cd"


Blog: lucd.info  Twitter: @LucD22  Co-author PowerCLI Reference

Reply
0 Kudos