VMware Cloud Community
MichaelRyom
Hot Shot
Hot Shot

PowerCli/Start-transcript bug

Hi

I have an old script(from 2020, running monthly as a windows schedule task) which seems to be failing recently (less than 6 month ago). Checking the log showed an (almost) empty log file.

In this script I'm using the powershell command start-transcript, to catch output and errors. A lazy mans logging.

But it seems that with one of the recent PowerCli version, PowerCli breaks the Start-transcript command for some reason.

Running the below code as a schedule task (using an AD user, which is local admin)

 

Start-Transcript -Path "C:\temp\test.log" -Append -Force
import-module VMware.PowerCli -force
Write-host "Hallo World!"
Stop-Transcript

 

Output

 

**********************
Windows PowerShell transcript start
Start time: 20220518103905
Username: xxx\xxx
RunAs User: xxx\xxx
Configuration Name: 
Machine: xxx (Microsoft Windows NT 10.0.17763.0)
Host Application: powershell.exe -file C:\scripts\repository\Scheduled Scripts\Capcity Report\test.ps1
Process ID: 27140
PSVersion: 5.1.17763.2803
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.17763.2803
BuildVersion: 10.0.17763.2803
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\temp\test.log
**********************
Windows PowerShell transcript end
End time: 20220518103913
**********************

 

Note no "Hallo World!"

If I run this code instead the same way as above

 

import-module VMware.PowerCli -force
Start-Transcript -Path "C:\temp\test.log" -Append -Force
Write-host "Hallo World!"
Stop-Transcript

 

Output

 

**********************
Windows PowerShell transcript start
Start time: 20220518104935
Username: xxx\xxx
RunAs User: xxx\xxx
Configuration Name: 
Machine: xxx(Microsoft Windows NT 10.0.17763.0)
Host Application: powershell.exe -file C:\scripts\repository\Scheduled Scripts\Capcity Report\test.ps1
Process ID: 20956
PSVersion: 5.1.17763.2803
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.17763.2803
BuildVersion: 10.0.17763.2803
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\temp\test.log
Hallo World!
**********************
Windows PowerShell transcript end
End time: 20220518104935
**********************

 

 Note "Hallo World!" is now in the output.

So it seems to be a bug in PowerCli, when modules are being loaded. I first noticed this issue when just running a command ( $cred = Get-VICredentialStoreItem -File $TokenFilePath ) and then did the testing with import-module, which seems to produce the same result.

Running this first script manually (in a powershell console) produces this result in the log file

 

**********************
Windows PowerShell transcript start
Start time: 20220518105520
Username: xxx\xxx
RunAs User: xxx\xxx
Configuration Name: 
Machine: xxx(Microsoft Windows NT 10.0.17763.0)
Host Application: C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
Process ID: 21748
PSVersion: 5.1.17763.2803
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.17763.2803
BuildVersion: 10.0.17763.2803
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\temp\test.log
PS C:\Users\xxx> import-module VMware.PowerCli -force
**********************
Windows PowerShell transcript end
End time: 20220518105528
**********************

 

and here is the output in the console

 

PS C:\Users\xxx> Start-Transcript -Path "C:\temp\test.log" -Append -Force
Transcript started, output file is C:\temp\test.log
PS C:\Users\xxx> import-module VMware.PowerCli -force
          Welcome to VMware PowerCLI!

Log in to a vCenter Server or ESX host:              Connect-VIServer
To find out what commands are available, type:       Get-VICommand
To show searchable help for all PowerCLI commands:   Get-PowerCLIHelp
Once you've connected, display all virtual machines: Get-VM
If you need more help, visit the PowerCLI community: Get-PowerCLICommunity

       Copyright (C) VMware, Inc. All rights reserved.


PS C:\Users\xxx> Write-host "Hallo World!"
Hallo World!
PS C:\Users\xxx> Stop-Transcript
Stop-Transcript : An error occurred stopping transcription: The host is not currently
transcribing.
At line:1 char:1
+ Stop-Transcript
+ ~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (:) [Stop-Transcript], PSInvalidOperationExc
   eption
    + FullyQualifiedErrorId : InvalidOperation,Microsoft.PowerShell.Commands.StopTranscriptC
   ommand

PS C:\Users\xxx>

 

Which seems to agree with me on the fact that something inside PowerCli module is stopping/failing the transcript commandlet. 😞

Can anyone reproduce this?

PowerCLI Version
----------------
VMware.PowerCLI 12.6.0 build 19610541
---------------
Component Versions
---------------
VMware Common PowerCLI Component 12.6 build 19600917
VMware Cis Core PowerCLI Component PowerCLI Component 12.6 build 19601368
VMware VimAutomation VICore Commands PowerCLI Component PowerCLI Component 12.6 build 19601570

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
41 Replies
LucD
Leadership
Leadership

Just a quick question, why do you explicitly import modules?
If the modules are in one of the directories listed in $env: PSModulePath there is no need for that.

Also, importing VMware.PowerCLI, implicit or explicit, generates a number of verbose message (where they inform you about the CEIP).
This might cause the transcript issues.
Perhaps try piping the Import-Module to Out-Null


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

Reply
0 Kudos
LucD
Leadership
Leadership

As additional info, the Start-Transcript cmdlet is notorious for mssing output.
See for example #Issue10994 on the PowerShell repository.

I'm not sure if what you are seeing is caused by PowerCLI, I sooner suspect the type of output some PowerCLI modules produce when loaded might confuse the Start-TRanscript


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

Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

Hi Luc

I don't explicitly import the module, only here to show case the issue. The original commandlet I used where is failed is Get-VICredentialStoreItem, but also Connect-OMServer does it and others (and here I do not import the module - The orginal script is more than 2000 lines of code so not something I can or will share here 🙂 ). That is why I started testing with import-module.

The VMware.PowerCli module(s) are in path $env: PSModulePath.

CEIP was been disabled for all users, so that should not be an issue and havn't been before.

Testing with "import-module VMware.PowerCli -force | Out-Null" does not work, same issue.

 

My laptop is running PowerCli 12.0.5 19195797 and the problem does not seem to be in this version.

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
LucD
Leadership
Leadership

In which PowerCLI version do you see the problem then?


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

Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

PowerCLI Version
----------------
VMware.PowerCLI 12.6.0 build 19610541
---------------
Component Versions
---------------
VMware Common PowerCLI Component 12.6 build 19600917
VMware Cis Core PowerCLI Component PowerCLI Component 12.6 build 19601368
VMware VimAutomation VICore Commands PowerCLI Component PowerCLI Component 12.6 build 19601570
Blogging at https://MichaelRyom.dk
Reply
0 Kudos
CLRYN
Contributor
Contributor

I have the exact same error on multible Windows computers. I think it started after a Windows patch some months ago. 

Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

Okay, interesting. Will update my laptop which is window 11 and powercli 12.5 to 12.6 to see what is does then.

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

I have upgraded an tested on 12.6 on Windows 11 and it works here 🙂

Do you have any idea to which windows update that might be at fault?

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
LucD
Leadership
Leadership

Looking back at the beginning of this thread, I noticed that where it fails PowerShell is called with 

C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe

Could the one that works perhaps have picked up

%SystemRoot%\syswow64\WindowsPowerShell\v1.0\powershell.exe

 Would that make a difference?


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

Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

Nice catch Luc

But still no luck

**********************
Windows PowerShell transcript start
Start time: 20220519072841
Username: xxx\xxx
RunAs User: xxx\xxx
Configuration Name: 
Machine: xxx(Microsoft Windows NT 10.0.17763.0)
Host Application: C:\Windows\syswow64\WindowsPowerShell\v1.0\powershell.exe
Process ID: 2648
PSVersion: 5.1.17763.2803
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.17763.2803
BuildVersion: 10.0.17763.2803
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\temp\test.log
PS C:\Windows\syswow64\WindowsPowerShell\v1.0> import-module VMware.PowerCli -force | Out-Null
**********************
Windows PowerShell transcript end
End time: 20220519072849
**********************
Blogging at https://MichaelRyom.dk
Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

Just to make sure you understand why I say it's a PowerCli issue. Here you can see me loading a non VMware module and you can see it working as expected.

**********************
Windows PowerShell transcript start
Start time: 20220519084317
Username: xxx\xxx
RunAs User: xxx\xxx
Configuration Name: 
Machine: xxx (Microsoft Windows NT 10.0.17763.0)
Host Application: C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
Process ID: 5696
PSVersion: 5.1.17763.2803
PSEdition: Desktop
PSCompatibleVersions: 1.0, 2.0, 3.0, 4.0, 5.0, 5.1.17763.2803
BuildVersion: 10.0.17763.2803
CLRVersion: 4.0.30319.42000
WSManStackVersion: 3.0
PSRemotingProtocolVersion: 2.3
SerializationVersion: 1.1.0.1
**********************
Transcript started, output file is C:\temp\test.log
PS C:\Users\xxx> import-module ActiveDirectory
PS C:\Users\xxx> Write-host "Hallo World!"
Hallo World!
PS C:\Users\xxx> Stop-Transcript
**********************
Windows PowerShell transcript end
End time: 20220519084321
**********************

 

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
LucD
Leadership
Leadership

I understand, but I'm still somewhat convinced it is the unhealthy habit of the PowerCLI modules to show those messages when the modules are loaded.
Most other modules don't do that.
Combine that with a new "flaw" in Start-Transcript, and I suspect it might be a combination of the two.

Btw, I have asked ages ago to remove those messages.
See Eliminate, or provide option with | VMware PowerCLI (aha.io)


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

Reply
0 Kudos
MichaelRyom
Hot Shot
Hot Shot

Thanks Luc.

We have another way of logging today internally, so I will just migrate the script to that way of logging instead of using transcript 🙂

 

Thanks for everybody's help. Think I will leave it at that 🙂

Blogging at https://MichaelRyom.dk
Reply
0 Kudos
Tocano
Enthusiast
Enthusiast

Just to confirm, this still appears to be an issue in 12.7

We just upgraded from 12.3 and have begun to encounter this very issue.

Right after the line:

VERBOSE: Dot-sourcing the script file 'C:\Program Files\WindowsPowerShell\Modules\VMware.VimAutomation.Common\12.7.0.20067789\net45\VMware.VimAutomation.Common.ps1'.
**********************
Windows PowerShell transcript end
End time: 20220719084406
**********************

We are now explicitly loading the VMware.VimAutomation.Common module in the profile, before we start our script transcript, in order to avoid this issue.

Reply
0 Kudos
AtanasAtanasov
VMware Employee
VMware Employee

I was not able to reproduce this.

Can you try to edit that file and see if this changes anything - '...\Modules\VMware.VimAutomation.Common\12.7.0.20067789\net45\VMware.VimAutomation.Common.ps1'?

(use the location from where you load the module from).

For example make it empty first and see if that changes anything - if it does, try to remove sections of it until you find what is making the difference.

Reply
0 Kudos
Tocano
Enthusiast
Enthusiast

Thank you for the follow up. 

Steps to reproduce:

  1. Launch powershell 5.1 console with empty profile (no autoloading modules)
  2. > $VerbosePreference = "Continue"
  3. > Start-Transcript -Path "C:\temp\$(Get-Date -format "yyyy-MM-dd")_Transcript.log
  4. > Get-Process
  5. > Import-Module VMware.PowerCLI

If you open the transcript file, you'll notice that it begins logging lines, but at some point during the middle of that import process, it stops logging and closes the transcript file properly with a Windows PowerShell transcript end and an End time.


As for your troubleshooting suggestion, that was a good idea. And initially, when I opened VMware.VimAutomation.Common.ps1 and commented out the content, and relaunched a new console, the transcript would progress, but still end - just this time at like VMware.VimAutomation.Cis.Core.ps1.  When I edited that file and commented out the content, it would progress to VMware.VimAutomation.Core.ps1. And commenting that one resulted in the transcript ending at VMware.VimAutomation.ViCore.Cmdlets.dll - and since I don't know how to edit a dll, that's where I stalled.

This is starting to feel like a line involving ending a running debugging transcript was accidentally left in a function of the compiled code and is getting called at the conclusion of each (or at least many) modules.

Thanks again for your suggestions. I'm still open to any troubleshooting recommendations.

Thank you.

 

Edit: Easier steps:

  1. Launch powershell 5.1 console with empty profile (no autoloading modules)
  2. > $VerbosePreference = "Continue"
  3. > Start-Transcript -Path "C:\temp\$(Get-Date -format "yyyy-MM-dd")_Transcript.log
  4. > Measure-Command {Get-VM} 

This will end in an error, but will import less modules and you'll still be able to see the log be stopped and closed prematurely. 

Reply
0 Kudos
AtanasAtanasov
VMware Employee
VMware Employee

The output for me in the .log file is exactly the same as what I see in the console.

What is the value of $PSVersionTable where you reproduced this? I tested this on Windows 11 (10.0.22000.653) and Window 10 (10.0.19041.1682), what version is the OS where you run this?

Reply
0 Kudos
Tocano
Enthusiast
Enthusiast

That's strange. 

PS > (Get-WmiObject -class Win32_OperatingSystem).Caption
Microsoft Windows Server 2019 Datacenter

PS > [System.Environment]::OSVersion.Version

Major Minor Build Revision
----- ----- ----- --------
10 0 17763 0

PS > $PSVersionTable

Name Value
---- -----
PSVersion 5.1.17763.2931
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.17763.2931
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1

PS > Get-Module -ListAvailable VMware.PowerCLI |ft -AutoSize
VERBOSE: Populating RepositorySourceLocation property for module VMware.PowerCLI.
VERBOSE: Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\VMware.PowerCLI\12.7.0.20091289\VMware.PowerCLI.ps1'.


Directory: C:\Program Files\WindowsPowerShell\Modules


ModuleType Version Name ExportedCommands
---------- ------- ---- ----------------
Manifest 12.7.0.20091289 VMware.PowerCLI

 

All of our servers experience this behavior. I'll have to try some wider testing. 

Thank you.

Reply
0 Kudos
AtanasAtanasov
VMware Employee
VMware Employee

Can you try with PowerShell Core?