(GH-872) Progress output never reaches completion #873

bill-long · 2016-07-25T04:03:32Z

Always pass -PercentComplete to Write-Progress, otherwise the output will
not be logged due to the -1 check.

Because we can reach 100% when there are a few bytes left to retrieve,
allow further logging of progress even if we reached 100%.

Closes #872
Closes #875

Always pass -PercentComplete to Write-Progress, otherwise the output will not be logged due to the -1 check. Because we can reach 100% when there are a few bytes left to retrieve, allow further logging of progress even if we reached 100%.

ferventcoder · 2016-07-25T12:37:26Z

PercentComplete work with Posh v2?

bill-long · 2016-07-25T15:48:27Z

Yes, however I just noticed another issue. If the output line is long enough to wrap, the trick of using "\r" to get back to the beginning and overwrite doesn't work.

PS C:\Users\administrator.BILONGTEST> $PSVersionTable.PSVersion

Major  Minor  Build  Revision
-----  -----  -----  --------
2      0      -1     -1


PS C:\Users\administrator.BILONGTEST> C:\ProgramData\chocolatey\choco install -y git --allow-unofficial
Chocolatey v0.9.10.3-147-gab78454

Chocolatey is not an official build (bypassed with --allow-unofficial).
 If you are seeing this message and it is not expected, your system may
 now be in a bad state. Only official builds are to be trusted.

Installing the following packages:
git
By installing you accept licenses for the packages.

git.install v2.9.2 [Approved]
Downloading git.install 64 bit
  from 'https://github.com/git-for-windows/git/releases/download/v2.9.2.windows.1/Git-2.9.2-64-bit.exe'
Progress: 100% - Completed download of C:\Users\administrator.BILONGTEST\AppData\Local\Temp\1\chocolatey\git.install\2.9
Progress: 100% - Completed download of C:\Users\administrator.BILONGTEST\AppData\Local\Temp\1\chocolatey\git.install\2.9
.2\Git-2.9.2-64-bit.exe (31.21 MB).
Download of Git-2.9.2-64-bit.exe (31.21 MB) completed.
Installing git.install...

Probably need to open a separate issue on that.

bill-long · 2016-07-25T15:56:11Z

Actually, it's not clear to me how that completion line is getting logged twice anyway. Completion will be the long one because it contains the whole file path. If we only log it once then we shouldn't get the duplication. Let me take another look at that. It might make sense to fix that as part of this PR.

ferventcoder · 2016-07-25T16:08:15Z

Actually, it's not clear to me how that completion line is getting logged twice anyway. Completion will be the long one because it contains the whole file path. If we only log it once then we shouldn't get the duplication. Let me take another look at that. It might make sense to fix that as part of this PR.

That's why I originally captured when we logged this so it wouldn't log twice.

ferventcoder · 2016-07-25T16:08:33Z

src/chocolatey/infrastructure/powershell/PoshHostUserInterface.cs

        public override void WriteProgress(long sourceId, ProgressRecord record)
        {  
            if (record.PercentComplete == -1) return;
-            if (hasLoggedFinalProgress) return;


@bill-long ^^

bill-long · 2016-07-25T17:58:45Z

Oh I see why. It's because it's a do/while. So on the final loop, let's say we read 5 bytes from $reader. That was the last 5 bytes of the file. We add that to $total, and because $total is now equal to $goal, we log completion.

But the while statement checks for $count -gt 0, and it was, so we go through the loop one more time. This time $count = 0, but before we get there, $total is still equal to $goal, so we log completion a second time. Then we exit the loop.

I'll add a commit to fix that behavior.

In Get-WebFile and Get-FtpFile, don't log completion until we read 0 bytes from the stream. Also, when calculating the percentage, round down instead of up so we don't log 100% until we are actually at 100%.

bill-long · 2016-07-25T21:33:29Z

Output is looking pretty good now:

Downloading git.install 64 bit
  from 'https://github.com/git-for-windows/git/releases/download/v2.9.2.windows.1/Git-2.9.2-64-bit.exe'
Progress: 100% - Completed download of C:\Users\administrator.BILONGTEST\AppData\Local\Temp\1\chocolatey\git.install\2.9
.2\Git-2.9.2-64-bit.exe (31.21 MB).
Download of Git-2.9.2-64-bit.exe (31.21 MB) completed.

Pad the progress output to ensure we cover the full width of the console, leaving no artifacts behind.

ferventcoder · 2016-07-26T19:38:42Z

src/chocolatey/infrastructure/powershell/PoshHostUserInterface.cs

@@ -129,7 +129,7 @@ public override void WriteProgress(long sourceId, ProgressRecord record)
            }

            // http://stackoverflow.com/a/888569/18475
-            Console.Write("\rProgress: {0}% - {1}".format_with(record.PercentComplete.to_string(), record.StatusDescription.PadRight(50, ' ')));
+            Console.Write("\rProgress: {0}% - {1}".format_with(record.PercentComplete.to_string(), record.StatusDescription).PadRight(Console.WindowWidth));


Where does this pull console.windowwidth from? There are issues with redirects. As long as it is using the Console abstraction, it should work fine.

It's System.Console.WindowWidth.

Docs: https://msdn.microsoft.com/en-us/library/system.console.windowwidth(v=vs.110).aspx
Source: http://referencesource.microsoft.com/mscorlib/a.html#19f2a20d8adf969c

According to the source code it is possible for it to throw an exception if we can't get a console handle, but I haven't been able to produce that state. I tested redirecting to a file from both powershell and cmd. I tested on Powershell 2.0 as well, and I tested Boxstarter, since it captures the choco output.

choco install -y 7zip --allow-unofficial > C:\users\bill\desktop\output.log

Produces this file:

Downloading 7zip.install 64 bit from 'http://www.7-zip.org/a/7z1602-x64.exe' Progress: 6% - Saving 92.41 KB of 1.31 MB (94632/1378550) Progress: 19% - Saving 266.36 KB of 1.31 MB (272752/1378550) Progress: 29% - Saving 397.53 KB of 1.31 MB (407072/1378550) Progress: 52% - Saving 705.5 KB of 1.31 MB (722432/1378550) Progress: 72% - Saving 980.68 KB of 1.31 MB (1004212/1378550) Progress: 85% - Saving 1.13 MB of 1.31 MB (1180872/1378550) Progress: 100% - Saving 1.31 MB of 1.31 MB (1378550/1378550) Progress: 100% - Completed download of C:\Users\bill\AppData\Local\Temp\chocolatey\7zip.install\16.02\7z1602-x64.exe (1.31 MB). Download of 7z1602-x64.exe (1.31 MB) completed.

Can you think of other scenarios I should test? I suppose we could throw some exception handling around it just in case, but so far I haven't found a scenario where that would be needed.

I can repro it. Let me find the issue and why you want to use Console adapter. Bonus is you are probably using it and don't realize it (unless you went and clicked on go to implementation aleady).

I was able to successfully repro issues with console handling in the beta.

Console adapter - https://github.com/chocolatey/choco/pull/873/files#diff-efd76cbe4b6a793d6856110d32039ec7R34

#572

https://github.com/chocolatey/choco/blob/master/src/chocolatey/infrastructure/adapters/Console.cs#L188

Ahh you're right, I was calling the adapter already without realizing it. Neat!

That's kind of the point of the adapters. 👍

ferventcoder · 2016-08-03T04:22:01Z

Merged into stable at 00c7b88

ferventcoder reviewed Jul 25, 2016
View reviewed changes

(GH-872) Progress output logs completion twice

dd0d0ce

In Get-WebFile and Get-FtpFile, don't log completion until we read 0 bytes from the stream. Also, when calculating the percentage, round down instead of up so we don't log 100% until we are actually at 100%.

ferventcoder mentioned this pull request Jul 26, 2016

Progress of download does not clear the whole output line #875

Closed

(GH-875) Pad progress output line to console width

3b3b1a0

Pad the progress output to ensure we cover the full width of the console, leaving no artifacts behind.

ferventcoder reviewed Jul 26, 2016
View reviewed changes

ferventcoder closed this Aug 3, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

(GH-872) Progress output never reaches completion #873

(GH-872) Progress output never reaches completion #873

bill-long commented Jul 25, 2016 •

edited by ferventcoder

ferventcoder commented Jul 25, 2016

bill-long commented Jul 25, 2016

bill-long commented Jul 25, 2016

ferventcoder commented Jul 25, 2016

ferventcoder Jul 25, 2016

bill-long commented Jul 25, 2016

bill-long commented Jul 25, 2016

ferventcoder Jul 26, 2016

bill-long Jul 26, 2016

ferventcoder Jul 27, 2016

ferventcoder Jul 27, 2016

ferventcoder Jul 27, 2016

ferventcoder Jul 27, 2016

bill-long Jul 27, 2016

ferventcoder Jul 27, 2016

ferventcoder commented Aug 3, 2016

(GH-872) Progress output never reaches completion #873

(GH-872) Progress output never reaches completion #873

Conversation

bill-long commented Jul 25, 2016 • edited by ferventcoder

ferventcoder commented Jul 25, 2016

bill-long commented Jul 25, 2016

bill-long commented Jul 25, 2016

ferventcoder commented Jul 25, 2016

Choose a reason for hiding this comment

bill-long commented Jul 25, 2016

bill-long commented Jul 25, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ferventcoder commented Aug 3, 2016

bill-long commented Jul 25, 2016 •

edited by ferventcoder