Double Messages

[username-is-already-taken2]

Hi there,

Thanks very much creating this tool.

I noticed ( I think with the latest version ) that I'm getting double messages within my console screen, I've attached an example

Can you see the text is repeated?

Gary

[EntranceJew]

I have also been having this bug happen to me, and I've come to find it's not just a visual glitch. Each command is actually being run twice, as evidenced by having cinst cygwin anywhere in your script, it will open the interactive installer and refuse to progress because its target destination already has files in it.

[mattdkerr]

Seeing this and using 2.9.26 of boxstarter, because boxstarter.azure requires it

[theheatDK]

Same on 2.10.3. I tried putting just a "Write-Host qwerty" in my script and the output is shown twice. In boxstarter.log I can see this: Running 'ChocolateyScriptRunner' for tmpF95E.tmp v1.0.0 with packageScript 'C:\ProgramData\chocolatey\lib\tmpF95E.tmp\tools\ChocolateyInstall.ps1', packageFolder:'C:\ProgramData\chocolatey\lib\tmpF95E.tmp', installArguments: '', packageParameters: '', Running 'C:\ProgramData\chocolatey\lib\tmpF95E.tmp\tools\ChocolateyInstall.ps1' [2018-02-08T15:45:57.6281446-08:00:::PID 1908] qwerty qwerty

[cwigley]

Does anyone know what the latest stable version is? I have tried backing out release by release to 2.9.14 but I am still running into problems with the duplicate commands causing the process to hang.

[Zamiell]

Just getting started with Boxstarter myself, and encountering this issue as well, every single line of output is duplicated. Very strange.

[Zamiell]

In the "boxstarter.log" file, only some lines are duplicated. Here's a snippet:

Chocolatey installed 1/1 packages. 0 packages failed.
 See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
Sending message 'PostRunMessage' out if there are subscribers...
[2018-05-12T23:50:52.0780568-04:00:::PID 5324] Boxstarter: restoring current directory location to C:\Windows\system32
[2018-05-12T23:50:52.0780568-04:00:::PID 5324] Boxstarter: found C:\Users\james\AppData\Local\Boxstarter\Boxstarter.5324.restart we are restarting
[2018-05-12T23:50:52.0940571-04:00:::PID 5324] Boxstarter: found C:\Users\james\AppData\Local\Boxstarter\Boxstarter.5324.restart we are restarting
[2018-05-12T23:50:52.1090538-04:00:::PID 5324] Boxstarter: Exit Code: 0
[2018-05-12T23:50:52.1411566-04:00:::PID 5324] ++ Boxstarter finished Calling Chocolatey to install tmp93D.tmp. This may take several minutes to complete... 00:04:18.9957038
[2018-05-12T23:50:52.1411566-04:00:::PID 5324] ++ Boxstarter finished Calling Chocolatey to install tmp93D.tmp. This may take several minutes to complete... 00:04:18.9957038
[2018-05-12T23:50:52.1575554-04:00:::PID 5324] Boxstarter: Removing C:\ProgramData\chocolatey\lib\tmp93D.tmp in progress
[2018-05-12T23:50:52.1730616-04:00:::PID 5324] Boxstarter: writing restart file
[2018-05-12T23:50:52.1730616-04:00:::PID 5324] Boxstarter: writing restart file
[2018-05-12T23:50:52.4630540-04:00:::PID 5324] Boxstarter: Restore Automatic Updates from Windows Update
[2018-05-12T23:50:52.4945508-04:00:::PID 5324] Boxstarter: UAC Enabled. Disabling...
[2018-05-12T23:50:52.5100548-04:00:::PID 5324] Boxstarter: Disabling UAC
[2018-05-12T23:50:52.5413599-04:00:::PID 5324] + Boxstarter finished Installation session. 00:04:22.2055366

[theheatDK]

I would love to help fix this but I have no idea how to debug it further. Any suggestions appreciates :-)

[ghost]

+1

[xhorntail]

Same issue here.

[adrianhalid]

Is there any update or work around for this?

[pauby]

Not at the moment. Happy to accept PR's as it's 'Up For Grabs'.

[adrianhalid]

I don't believe it is actually running the installation scripts twice.

I believe the issue is with Write-Host in which it is outputting the value twice to the powershell cli.

Interestingly if you execute boxstarter from within Powershell ISE you don't get the duplicate outputs from Write-Host.

To prove this I modified the Write-HostOverride function within the chocolatey.ps1 script.

I commented out all the code within this function and added two lines

Microsoft.PowerShell.Utility\Write-Host @PSBoundParameters
Log-BoxStarterMessage $object

This means that the overridden Write-Host functions writes to the console output and also to the log file. There results was that it was NOT entered twice in the log file. But in powershell CLI it was outputed twice.

I then changed the line for Write-Host to Write-Output $object

Microsoft.PowerShell.Utility\Write-Output $object

The result was that the output was only shown once in Powershell CLI.

I have not gotten to the bottom of it but don't believe the packages are getting executed twice.

I believe it is some type of bug with the Write-Host function because called within an Invoke-Command as the duplicate messages only show for the installations of the child packages and not the parent package.

I hope that helps with trying to find a solution. But it seems to only be a UI issue and not a functional issue.

[pauby]

@adrianhalid Thanks for that detailed troubleshooting. It is indeed only a UI / display issue and not a functional one.

If you get to the bottom of it then PR's are welcome.

[adrianhalid]

I think its a bug in PowerShell as per this Open issue. https://github.com/PowerShell/PowerShell/issues/7814

I can't absolutely prove this but looking at the behaviour I think its related.

If you read the issues comments you see it also affect the Invoke-Command.

I was trying to figure out if/which Invoke-Command might be causing the issue but couldn't figure it out. I wanted to try use the -InformationAction Ignore option to see if I could stop the message being passed up the nested Invoke_Command's.

Maybe someone who knows the code base better than me can figure out where the -InformationAction Ignore options could work. I am thinking it might actually have to be applied to the Chocolatey code base. But couldn't figure it out where.

Here is the example they provide which demonstrates the issue. You would expect the text "Test" to be displayed once. But with the nested Jobs/Commands it is echoed out to the display 6 times.

Start-Job {
Start-Job {
Start-Job {
Start-Job {
Start-Job {
    Write-Information Test -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue
} | Receive-Job -Wait -AutoRemoveJob -InformationAction Continue

Also, it is not jobs specific. It is how PowerShell remoting work in general:

Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
Invoke-Command . {
    Write-Information Test -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue
} -EnableNetworkAccess -InformationAction Continue