[do not merge] Testing: debug failing build on Windows RS5 #39403

thaJeztah · 2019-06-24T16:53:20Z

relates to #39402

Windows RS5 builds started to fail recently;

15:20:17 INFO: Extracting git...
15:20:31 INFO: Expanding go...
15:20:36 Remove-Item : Cannot find path 'C:\go\' because it does not exist.
15:20:36 At C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch
15:20:36 ive\Microsoft.PowerShell.Archive.psm1:411 char:46
15:20:36 + ...                 $expandedItems | % { Remove-Item $_ -Force -Recurse }
15:20:36 +                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
15:20:36     + CategoryInfo          : ObjectNotFound: (C:\go\:String) [Remove-Item], I
15:20:36    temNotFoundException
15:20:36     + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.Remov
15:20:36    eItemCommand
15:20:36

That error looks to be triggered by the step downloading Go;

moby/Dockerfile.windows

Lines 214 to 215 in 6f446d0

    
           Write-Host INFO: Downloading go...; ` 
        
           Download-File $('https://golang.org/dl/go'+$Env:GO_VERSION+'.windows-amd64.zip') C:\go.zip; `

Write-Host INFO: Downloading go...; `
Download-File $('https://golang.org/dl/go'+$Env:GO_VERSION+'.windows-amd64.zip') C:\go.zip; `

The codepath that is causing the actual error is in;
https://github.com/PowerShell/Microsoft.PowerShell.Archive/blob/v1.0.0.0/Microsoft.PowerShell.Archive/Microsoft.PowerShell.Archive.psm1#L400-L408

And is only triggered if extracting the archive fails:

if($isArchiveFileProcessingComplete -eq $false)
{
    if($expandedItems.Count -gt 0)
    {
        # delete the expanded file/directory as the archive
        # file was not completly expanded.
        $expandedItems | % { Remove-Item $_ -Force -Recurse }
    }
}

Trying to download the previous version of Go to check if there's something different
with the archive we're downloading.

Signed-off-by: Sebastiaan van Stijn github@gone.nl

- What I did

- How I did it

- How to verify it

- Description for the changelog

- A picture of a cute animal (not mandatory but encouraged)

thaJeztah · 2019-06-24T16:58:25Z

Interesting; it now fails when downloading Git; https://jenkins.dockerproject.org/job/Docker-PRs-WoW-RS5-Process/2810/console

16:54:48 INFO: Extracting git...
16:55:08 Remove-Item : Cannot find path 'C:\git-tmp\_rels' because it does not exist.
16:55:08 At C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch
16:55:08 ive\Microsoft.PowerShell.Archive.psm1:411 char:46
16:55:08 + ...                 $expandedItems | % { Remove-Item $_ -Force -Recurse }
16:55:08 +                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
16:55:08     + CategoryInfo          : ObjectNotFound: (C:\git-tmp\_rels:String) [Remov 
16:55:08    e-Item], ItemNotFoundException
16:55:08     + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.Remov 
16:55:08    eItemCommand
16:55:08

Wonder if it's some networking issue

thaJeztah · 2019-06-24T17:23:00Z

Changing to use -Force;

Expand-Archive C:\go.zip -DestinationPath C:\ -Force;

Now produces a different error:

17:13:45 INFO: Expanding go...
17:13:58 �[91mRemove-Item : Access is denied
17:13:58 �[0m�[91mAt C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch
17:13:58 �[0m�[91mive\Microsoft.PowerShell.Archive.psm1:411 char:46
17:13:58 + ...                 $expandedItems | % { Remove-Item $_ -Force -Recurse }
17:13:58 �[0m�[91m+                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
17:13:58     + CategoryInfo          : PermissionDenied: (C:\go\:String) [Remove-Item], 
17:13:58 �[0m�[91m    UnauthorizedAccessException
17:13:58     + FullyQualifiedErrorId : ItemExistsUnauthorizedAccessError,Microsoft.Powe 
17:13:58    rShell.Commands.RemoveItemCommand
17:13:58 �[0m�[91m 
17:13:59 �[0m

Possibly because it tries to remove C:\ (which would obviously fail)

codecov · 2019-06-24T17:25:03Z

Codecov Report

❗ No coverage uploaded for pull request base (master@baa0040). Click here to learn what that means.
The diff coverage is n/a.

@@            Coverage Diff            @@
##             master   #39403   +/-   ##
=========================================
  Coverage          ?   37.32%           
=========================================
  Files             ?      609           
  Lines             ?    45197           
  Branches          ?        0           
=========================================
  Hits              ?    16869           
  Misses            ?    26039           
  Partials          ?     2289

thaJeztah · 2019-06-24T17:25:12Z

Removed the -Force again; trying Go 1.12.5 again

edit: argh

17:25:56 ERROR: Failed 'ERROR: Mismatched GO versions between Dockerfile and Dockerfile.windows. Update your PR to ensure that both files are updated and in sync. 1.12.6 1.12.5' at 06/24/2019 17:25:56
17:25:56 At C:\gopath\src\github.com\docker\docker\hack\ci\windows.ps1:448 char:9
17:25:56 +         Throw "ERROR: Mismatched GO versions between Dockerfile and D ...

thaJeztah · 2019-06-24T17:35:12Z

Same with Go 1.12.5; trying the same approach as Git now (temp directory, then move)

edit: no luck there

trying ADD <go download url> - perhaps something weird is happening with the downloads

Windows RS5 builds started to fail recently; ``` 15:20:17 INFO: Extracting git... 15:20:31 INFO: Expanding go... 15:20:36 Remove-Item : Cannot find path 'C:\go\' because it does not exist. 15:20:36 At C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch 15:20:36 ive\Microsoft.PowerShell.Archive.psm1:411 char:46 15:20:36 + ... $expandedItems | % { Remove-Item $_ -Force -Recurse } 15:20:36 + ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 15:20:36 + CategoryInfo : ObjectNotFound: (C:\go\:String) [Remove-Item], I 15:20:36 temNotFoundException 15:20:36 + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.Remov 15:20:36 eItemCommand 15:20:36 ``` That error looks to be triggered by the step downloading Go; https://github.com/moby/moby/blob/6f446d041bfd690856e63e1515d0d9514f9b684a/Dockerfile.windows#L214-L215 ``` Write-Host INFO: Downloading go...; ` Download-File $('https://golang.org/dl/go'+$Env:GO_VERSION+'.windows-amd64.zip') C:\go.zip; ` ``` The codepath that is causing the actual error is in; https://github.com/PowerShell/Microsoft.PowerShell.Archive/blob/v1.0.0.0/Microsoft.PowerShell.Archive/Microsoft.PowerShell.Archive.psm1#L400-L408 And is only triggered if extracting the archive fails: ```powershell if($isArchiveFileProcessingComplete -eq $false) { if($expandedItems.Count -gt 0) { # delete the expanded file/directory as the archive # file was not completly expanded. $expandedItems | % { Remove-Item $_ -Force -Recurse } } } ``` Trying to download the previous version of Go to check if there's something different with the archive we're downloading. Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah · 2019-06-24T17:42:21Z

OK, that worked, so looks like Download-File is broken when downloading Go 🤔

17:40:48 INFO: Extracting git...
17:41:00 INFO: Expanding go...
17:41:24 INFO: Expanding compiler 1 of 3...
17:41:25 INFO: Expanding compiler 2 of 3...

thaJeztah · 2019-06-24T18:03:41Z

Wondering if it's because a redirect isn't followed;

* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
< HTTP/2 302 
< date: Mon, 24 Jun 2019 18:02:30 GMT
< content-type: text/html; charset=utf-8
< content-length: 74
< location: https://dl.google.com/go/go1.12.6.windows-amd64.zip
< strict-transport-security: max-age=31536000; includeSubDomains; preload
< via: 1.1 google
< alt-svc: quic=":443"; ma=2592000; v="46,44,43,39"
<

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah · 2019-06-24T18:08:06Z

Changed to use the redirect URL, but that doesn't solve the issue;


18:07:25 INFO: Expanding go...
18:07:30 Remove-Item : Cannot find path 'C:\go\' because it does not exist.
18:07:30 At C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch
18:07:30 ive\Microsoft.PowerShell.Archive.psm1:411 char:46
18:07:30 + ...                 $expandedItems | % { Remove-Item $_ -Force -Recurse }
18:07:30 +                                          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
18:07:30     + CategoryInfo          : ObjectNotFound: (C:\go\:String) [Remove-Item], I 
18:07:30    temNotFoundException
18:07:30     + FullyQualifiedErrorId : PathNotFound,Microsoft.PowerShell.Commands.Remov 
18:07:30    eItemCommand
18:07:30

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah · 2019-06-24T18:27:57Z

Hm.. looks like there's a networking issue; I changed to use the mcr.microsoft.com/windows/servercore:1809 image to exclude the possibility there's something wrong with the image that's pre-loaded on the machines, but pulling that image fails:

18:24:52 Step 1/7 : FROM mcr.microsoft.com/windows/servercore:1809
18:24:53 1809: Pulling from windows/servercore
18:24:53 65014b3c3121: Pulling fs layer
18:24:53 266cffe9d908: Pulling fs layer
18:24:58 266cffe9d908: Retrying in 5 seconds
18:24:59 266cffe9d908: Retrying in 4 seconds
18:24:59 65014b3c3121: Retrying in 5 seconds
18:25:00 266cffe9d908: Retrying in 3 seconds
18:25:00 65014b3c3121: Retrying in 4 seconds
18:25:01 266cffe9d908: Retrying in 2 seconds
18:25:01 65014b3c3121: Retrying in 3 seconds
18:25:02 266cffe9d908: Retrying in 1 second
18:25:02 65014b3c3121: Retrying in 2 seconds
18:25:03 266cffe9d908: Retrying in 10 seconds
18:25:03 65014b3c3121: Retrying in 1 second
18:25:04 266cffe9d908: Retrying in 9 seconds
18:25:04 65014b3c3121: Retrying in 10 seconds
18:25:05 266cffe9d908: Retrying in 8 seconds
18:25:05 65014b3c3121: Retrying in 9 seconds
18:25:06 266cffe9d908: Retrying in 7 seconds
18:25:06 65014b3c3121: Retrying in 8 seconds
18:25:07 266cffe9d908: Retrying in 6 seconds

thaJeztah · 2019-06-25T17:09:02Z

So.. changing the base image worked;

21:54:40 Step 1/7 : FROM mcr.microsoft.com/windows/servercore:1809
21:54:40 1809: Pulling from windows/servercore
21:54:41 65014b3c3121: Pulling fs layer
21:54:41 266cffe9d908: Pulling fs layer
21:54:49 266cffe9d908: Download complete
21:55:06 65014b3c3121: Verifying Checksum
21:55:06 65014b3c3121: Download complete
21:57:27 65014b3c3121: Pull complete
21:59:52 266cffe9d908: Pull complete
21:59:52 Digest: sha256:370afa846b124b4674257e193352b38c65790ef75bce27418da0738fa208e66a
21:59:52 Status: Downloaded newer image for mcr.microsoft.com/windows/servercore:1809
...

21:59:59 INFO: Downloading git...
22:00:00 INFO: Downloading go...
22:00:02 INFO: Downloading compiler 1 of 3...
22:00:03 INFO: Downloading compiler 2 of 3...
22:00:03 INFO: Downloading compiler 3 of 3...
22:00:04 INFO: Extracting git...
22:00:17 INFO: Expanding go...
22:00:39 INFO: Expanding compiler 1 of 3...
22:00:41 INFO: Expanding compiler 2 of 3...
22:00:46 INFO: Expanding compiler 3 of 3...
22:00:47 INFO: Removing downloaded files...

And it fails on the image that's preloaded on the machine;

21:54:13 INFO: Running in C:\gopath\src\github.com\docker\docker
21:54:13 INFO: docker/docker repository was found
21:54:13 INFO: Image microsoft/windowsservercore:latest is already loaded in the control daemon
21:54:13 INFO: Version of microsoft/windowsservercore:latest is '10.0.17763.437'
21:54:13 INFO: Docker version of control daemon

...

22:05:33 INFO: Loading windowsservercore .tar from disk into the daemon under test. This may take some time...
22:07:59 Loaded image: microsoft/windowsservercore:10.0.17763.437
22:07:59 Loaded image: microsoft/windowsservercore:latest
22:07:59 INFO: docker load of windowsservercore  into daemon under test completed successfully
22:07:59 INFO: Version of microsoft/windowsservercore:latest is '10.0.17763.437'

So looks like that image is broken

thaJeztah · 2019-06-25T17:10:56Z

Checking the what version the 1809 image is, and looks like that's more recent than the one that's preloaded (10.0.17763.557 versus 10.0.17763.437)

docker manifest inspect mcr.microsoft.com/windows/servercore:1809

{
   "schemaVersion": 2,
   "mediaType": "application/vnd.docker.distribution.manifest.list.v2+json",
   "manifests": [
      {
         "mediaType": "application/vnd.docker.distribution.manifest.v2+json",
         "size": 945,
         "digest": "sha256:1daf90c37624fb4abe9556a0d2b8852d866ec62e9696d381a4000ae56c74c362",
         "platform": {
            "architecture": "amd64",
            "os": "windows",
            "os.version": "10.0.17763.557"
         }
      }
   ]
}

This reverts commit f0092a8. Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah · 2019-06-25T17:12:20Z

Reverting the URL change to confirm that it's indeed an issue with the image

thaJeztah · 2019-06-25T18:03:28Z

Ok; build still succeeds, so looks to be an issue with that base image?

This reverts commit 62f5bd3. Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

ddebroy · 2019-07-02T21:46:37Z

It appears the issue is specific to one of the VMs: azure-windows-rs5-1. Could it be running out of temp disk space or something along the lines of that? The CI jobs on azure-windows-rs5-2 seem to go through smooth with identical version strings wrt the images.

thaJeztah · 2019-07-02T23:08:12Z

interesting; odd that we kept hitting those broken nodes then 😞

I'll close this for now; thanks!

GordonTheTurtle added the status/0-triage label Jun 24, 2019

thaJeztah added rebuild/windowsRS5-process and removed rebuild/windowsRS5-process labels Jun 24, 2019

GordonTheTurtle removed the rebuild/* label Jun 24, 2019

thaJeztah force-pushed the fix_rs5_powershell branch 3 times, most recently from 0b00f35 to cf56bf5 Compare June 24, 2019 17:12

thaJeztah force-pushed the fix_rs5_powershell branch from cf56bf5 to d6c920d Compare June 24, 2019 17:24

thaJeztah force-pushed the fix_rs5_powershell branch from d6c920d to c740d46 Compare June 24, 2019 17:30

thaJeztah force-pushed the fix_rs5_powershell branch from c740d46 to 27782da Compare June 24, 2019 17:35

thaJeztah force-pushed the fix_rs5_powershell branch from 27782da to 62f5bd3 Compare June 24, 2019 17:39

Use redirect URL

f0092a8

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah force-pushed the fix_rs5_powershell branch from 3c4be78 to f0092a8 Compare June 24, 2019 18:06

Use mcr.microsoft.com/windows/servercore:1809

64bb1e4

Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah mentioned this pull request Jun 24, 2019

Fix rate limiting for logger, increase refill rate #39360

Merged

Revert "Use redirect URL"

013bff2

This reverts commit f0092a8. Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

This was referenced Jun 26, 2019

seccomp: whitelist io-uring related system calls #39415

Merged

Update to using alpine 3.10 #39401

Merged

Revert "Testing: debug failing build on Windows RS5"

7d56772

This reverts commit 62f5bd3. Signed-off-by: Sebastiaan van Stijn <github@gone.nl>

thaJeztah closed this Jul 2, 2019

thaJeztah deleted the fix_rs5_powershell branch July 18, 2019 23:34

thaJeztah mentioned this pull request Jul 18, 2019

CI Failing on Windows RS5 due to missing C:\go #39402

Closed

	Write-Host INFO: Downloading go...; `
	Download-File $('https://golang.org/dl/go'+$Env:GO_VERSION+'.windows-amd64.zip') C:\go.zip; `

[do not merge] Testing: debug failing build on Windows RS5 #39403

[do not merge] Testing: debug failing build on Windows RS5 #39403

Uh oh!

Conversation

thaJeztah commented Jun 24, 2019

Uh oh!

thaJeztah commented Jun 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jun 24, 2019

Uh oh!

codecov bot commented Jun 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

thaJeztah commented Jun 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jun 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jun 24, 2019

Uh oh!

thaJeztah commented Jun 24, 2019

Uh oh!

thaJeztah commented Jun 24, 2019

Uh oh!

thaJeztah commented Jun 24, 2019

Uh oh!

thaJeztah commented Jun 25, 2019

Uh oh!

thaJeztah commented Jun 25, 2019

Uh oh!

thaJeztah commented Jun 25, 2019

Uh oh!

thaJeztah commented Jun 25, 2019

Uh oh!

ddebroy commented Jul 2, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented Jul 2, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

thaJeztah commented Jun 24, 2019 •

edited

Loading

codecov bot commented Jun 24, 2019 •

edited

Loading

thaJeztah commented Jun 24, 2019 •

edited

Loading

thaJeztah commented Jun 24, 2019 •

edited

Loading

ddebroy commented Jul 2, 2019 •

edited

Loading