search

GoogleContainerTools / skaffold

Easy and Repeatable Kubernetes Development
https://skaffold.dev/
Apache License 2.0
15.04k stars 1.62k forks source link

Skaffold hangs after pushing image to private docker registry #5851

Closed fabifrank closed 3 years ago

fabifrank commented 3 years ago

Expected behavior

Skaffold continues to deploy to cluster right after pushing image to private registry.

Actual behavior

Skaffold hangs for a while without notice (~ 18min) after pushing image to private registry.

Information

apiVersion: skaffold/v2beta10
kind: Config
build:
  tagPolicy:
    gitCommit: {}
  local:
    push: false
profiles:

- name: analytics
  build:
    local:
      push: true
    artifacts:
    - image: registry.somedomain.com:30004/postgres-analytics
      context: ./
  deploy:
    kubeContext: docker-for-desktop
    kubectl:
      manifests:
        - ./k8s/analytics/
    kustomize:
      paths:
        - ./k8s/analytics/

Please note: The same behaviour appears with kubeContext = minikube as well.

Steps to reproduce the behavior

  1. Deploy private docker registry with image registry.hub.docker.com/library/registry:2.7
  2. Configure docker to connect to the registry (TLS auth)
  3. Run skaffold run -v TRACE --profile=analytics
  4. Watch registry output (log)
  5. Wait for skaffold being stuck after successfully pushing the image to the registry.

Log of skaffold command (please note the 18min delay at the end):

skaffold run -vdebug --profile=analytics --kubeconfig=~/.kube/syna.yml
INFO[0000] Skaffold &{Version:v1.24.0 ConfigVersion:skaffold/v2beta16 GitVersion: GitCommit:90023150fe626f57f8702384cb0a5e06457069ec BuildDate:2021-05-14T06:12:00Z GoVersion:go1.16.3 Compiler:gc Platform:darwin/amd64 User:} 
INFO[0000] Loaded Skaffold defaults from "/Users/skober/.skaffold/config" 
INFO[0000] Could not open skaffold.yaml: "open skaffold.yaml: no such file or directory" 
INFO[0000] Trying to read from skaffold.yml instead     
DEBU[0000] config version out of date: upgrading to latest "skaffold/v2beta16" 
DEBU[0000] parsed 1 configs from configuration file /Users/skober/Documents/dev/syna/postgres/skaffold.yaml 
INFO[0000] applying profile: analytics                  
DEBU[0000] overlaying profile on config for field Build 
DEBU[0000] overlaying profile on config for field artifacts 
DEBU[0000] overlaying profile on config for field insecureRegistries 
DEBU[0000] overlaying profile on config for field tagPolicy 
INFO[0000] no values found in profile for field TagPolicy, using original config values 
DEBU[0000] overlaying profile on config for field BuildType 
DEBU[0000] overlaying profile on config for field Test  
DEBU[0000] overlaying profile on config for field Deploy 
DEBU[0000] overlaying profile on config for field DeployType 
DEBU[0000] overlaying profile on config for field helm  
DEBU[0000] overlaying profile on config for field kpt   
DEBU[0000] overlaying profile on config for field kubectl 
DEBU[0000] overlaying profile on config for field kustomize 
DEBU[0000] overlaying profile on config for field statusCheck 
DEBU[0000] overlaying profile on config for field statusCheckDeadlineSeconds 
DEBU[0000] overlaying profile on config for field kubeContext 
DEBU[0000] overlaying profile on config for field logs  
DEBU[0000] overlaying profile on config for field prefix 
DEBU[0000] overlaying profile on config for field PortForward 
INFO[0000] Activated kube-context "docker-for-desktop"  
INFO[0000] Using kubectl context: docker-for-desktop    
DEBU[0000] Running command: [minikube version --output=json] 
DEBU[0000] could not parse date ""                      
DEBU[0000] Command output: [{"commit":"c61663e942ec43b20e8e70839dcca52e44cd85ae","minikubeVersion":"v1.20.0"}
] 
DEBU[0000] setting Docker user agent to skaffold-v1.24.0 
DEBU[0000] Using builder: local                         
INFO[0000] build concurrency first set to 1 parsed from *local.Builder[0] 
INFO[0000] final build concurrency value is 1           
Generating tags...
 - registry.somedomain.com:15236/postgres-analytics -> DEBU[0000] Running command: [git describe --tags --always] 
DEBU[0000] Command output: [195/e0fa454/master-68-ga5bd51e
] 
WARN[0000] Using "195_e0fa454_master-68-ga5bd51e" instead of "195/e0fa454/master-68-ga5bd51e" as an image tag 
DEBU[0000] Running command: [git status . --porcelain]  
DEBU[0000] Command output: [ M Makefile
 M skaffold.yml
] 
registry.somedomain.com:15236/postgres-analytics:195_e0fa454_master-68-ga5bd51e-dirty
INFO[0000] Tags generated in 51.239263ms                
Checking cache...
DEBU[0000] Found dependencies for dockerfile: [{contents/usr/bin /usr/bin true} {postgres /etc/postgresql true}] 
DEBU[0000] Could not import artifact from Docker, building instead (import of missing images disabled) 
 - registry.somedomain.com:15236/postgres-analytics: Not found. Building
INFO[0000] Cache check completed in 16.075405ms         
Starting build...
Found [docker-for-desktop] context, using local docker daemon.
Building [registry.somedomain.com:15236/postgres-analytics]...
DEBU[0000] Running docker build: context: ./, dockerfile: Dockerfile 
Sending build context to Docker daemon   42.5kB
Step 1/13 : FROM postgres:12.7
 ---> b98f3fad83fd
Step 2/13 : RUN apt-get update && apt-get upgrade -y
 ---> Using cache
 ---> 578ac9081fc8
Step 3/13 : RUN apt-get install bzip2 -y
 ---> Using cache
 ---> e51752b5b2d1
Step 4/13 : RUN apt-get install -y python-pip
 ---> Using cache
 ---> d51cfd5f19b8
Step 5/13 : RUN pip install awscli
 ---> Using cache
 ---> 55ea43f58ff9
Step 6/13 : RUN localedef -i en_US -f UTF-8 en_US.UTF-8
 ---> Using cache
 ---> 9427335866d5
Step 7/13 : ENV POSTGRES_VERSION "12"
 ---> Using cache
 ---> d01bca9bcf1e
Step 8/13 : RUN usermod -u 16235 postgres
 ---> Using cache
 ---> 4f71f50e19f3
Step 9/13 : RUN groupmod -g 16235 postgres
 ---> Using cache
 ---> 6c1ef248eb8e
Step 10/13 : USER postgres
 ---> Using cache
 ---> fd79cf38e13d
Step 11/13 : COPY ./contents/usr/bin/ /usr/bin/
 ---> Using cache
 ---> 206c4e3d70a9
Step 12/13 : COPY ./postgres/ /etc/postgresql/
 ---> Using cache
 ---> 7d2cb9c746d7
Step 13/13 : CMD ["/usr/bin/boot"]
 ---> Using cache
 ---> 20f684229363
Successfully built 20f684229363
Successfully tagged registry.somedomain.com:15236/postgres-analytics:195_e0fa454_master-68-ga5bd51e-dirty
The push refers to repository [registry.somedomain.com:15236/postgres-analytics]
548185991d11: Preparing
e78205ebfb27: Preparing
51f45420e30f: Preparing
62dcdee93025: Preparing
4d85af14008f: Preparing
db3fcbdd3594: Preparing
0caabd4869ed: Preparing
34a7e1997337: Preparing
2b248bb371e7: Preparing
da9a2593df77: Preparing
25fd228b2b6f: Preparing
cf057453b4b7: Preparing
8b0b5a0e0156: Preparing
015fc6ae53f2: Preparing
c32ba26bc45e: Preparing
aae7b3e8092c: Preparing
4990c862bcb1: Preparing
783d2b10b501: Preparing
65511fb7fe40: Preparing
a23cc4a81fd4: Preparing
855f2bb415b9: Preparing
bdec2b2d7e4a: Preparing
02c055ef67f5: Preparing
db3fcbdd3594: Waiting
0caabd4869ed: Waiting
34a7e1997337: Waiting
2b248bb371e7: Waiting
da9a2593df77: Waiting
25fd228b2b6f: Waiting
cf057453b4b7: Waiting
8b0b5a0e0156: Waiting
015fc6ae53f2: Waiting
65511fb7fe40: Waiting
c32ba26bc45e: Waiting
aae7b3e8092c: Waiting
a23cc4a81fd4: Waiting
4990c862bcb1: Waiting
783d2b10b501: Waiting
bdec2b2d7e4a: Waiting
02c055ef67f5: Waiting
855f2bb415b9: Waiting
62dcdee93025: Layer already exists
548185991d11: Layer already exists
4d85af14008f: Layer already exists
51f45420e30f: Layer already exists
e78205ebfb27: Layer already exists
db3fcbdd3594: Layer already exists
2b248bb371e7: Layer already exists
34a7e1997337: Layer already exists
da9a2593df77: Layer already exists
25fd228b2b6f: Layer already exists
cf057453b4b7: Layer already exists
8b0b5a0e0156: Layer already exists
015fc6ae53f2: Layer already exists
aae7b3e8092c: Layer already exists
783d2b10b501: Layer already exists
65511fb7fe40: Layer already exists
4990c862bcb1: Layer already exists
a23cc4a81fd4: Layer already exists
bdec2b2d7e4a: Layer already exists
855f2bb415b9: Layer already exists
02c055ef67f5: Layer already exists

 >>> Comment: This is where it hangs for 18 min <<<

195_e0fa454_master-68-ga5bd51e-dirty: digest: sha256:ac8c29de3c8f61a7b375bc48b22f3ab37f2cba03819db9416a30ab67e9972596 size: 5132
INFO[1094] Build completed in 18 minutes 13.824 seconds 
Starting test...
INFO[1094] Test completed in 27.919µs                   
Tags used in deployment:
 - registry.somedomain.com:15236/syna-postgres-analytics -> registry.somedomain.com:15236/syna-postgres-analytics:195_e0fa454_master-68-ga5bd51e-dirty@sha256:ac8c29de3c8f61a7b375bc48b22f3ab37f2cba03819db9416a30ab67e9972596
DEBU[1094] getting client config for kubeContext: `docker-for-desktop` 
DEBU[1094] Running command: [tput colors]               
DEBU[1094] Command output: [256

Log of docker registry:

time="2021-05-15T10:45:38.710909952Z" level=debug msg="authorizing request" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=33237a16-397f-4569-a09d-7a58dbd71314 http.request.method=HEAD http.request.remoteaddr="X.X.X.X:57144" http.request.uri="/v2/postgres-analytics/blobs/sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" vars.digest="sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" vars.name=postgres-analytics 
time="2021-05-15T10:45:38.710986617Z" level=debug msg=GetBlob go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=33237a16-397f-4569-a09d-7a58dbd71314 http.request.method=HEAD http.request.remoteaddr="X.X.X.X:57144" http.request.uri="/v2/postgres-analytics/blobs/sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" vars.digest="sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" vars.name=postgres-analytics 
time="2021-05-15T10:45:38.711233493Z" level=debug msg="s3aws.URLFor("/docker/registry/v2/blobs/sha256/69/69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696/data")" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=33237a16-397f-4569-a09d-7a58dbd71314 http.request.method=HEAD http.request.remoteaddr="X.X.X.X:57144" http.request.uri="/v2/postgres-analytics/blobs/sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" trace.duration=170.832µs trace.file="/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).URLFor" trace.id=6cd87a02-83f6-4bb5-a2db-7e0090f931c3 trace.line=217 vars.digest="sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" vars.name=postgres-analytics 
time="2021-05-15T10:45:38.711406269Z" level=info msg="response completed" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=33237a16-397f-4569-a09d-7a58dbd71314 http.request.method=HEAD http.request.remoteaddr="X.X.X.X:57144" http.request.uri="/v2/postgres-analytics/blobs/sha256:69692152171afee1fd341febc390747cfca2ff302f2881d8b394e786af605696" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" http.response.contenttype="application/octet-stream" http.response.duration=1.512484ms http.response.status=307 http.response.written=0 
time="2021-05-15T10:45:38.939583482Z" level=debug msg="authorizing request" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=623c4531-ef4b-41a9-a34f-1cdfb8d1d673 http.request.method=PATCH http.request.remoteaddr="X.X.X.X:57146" http.request.uri="/v2/postgres-analytics/blobs/uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31?_state=5f1hDFZqA3hqPO031sZlqvdiV72Wlne6sqFkVf9ithl7Ik5hbWUiOiJzeW5hLXBvc3RncmVzLWFuYWx5dGljcyIsIlVVSUQiOiIzY2YzOWFhYy0wNDMxLTQ5OGEtOTY5MC1kY2ZlMmI0ZThjMzEiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMjEtMDUtMTVUMTA6NDU6MzguNDAwNTU0ODM0WiJ9" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" vars.name=postgres-analytics vars.uuid=3cf39aac-0431-498a-9690-dcfe2b4e8c31 
time="2021-05-15T10:45:38.939703919Z" level=debug msg="(*linkedBlobStore).Resume" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=623c4531-ef4b-41a9-a34f-1cdfb8d1d673 http.request.method=PATCH http.request.remoteaddr="X.X.X.X:57146" http.request.uri="/v2/postgres-analytics/blobs/uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31?_state=5f1hDFZqA3hqPO031sZlqvdiV72Wlne6sqFkVf9ithl7Ik5hbWUiOiJzeW5hLXBvc3RncmVzLWFuYWx5dGljcyIsIlVVSUQiOiIzY2YzOWFhYy0wNDMxLTQ5OGEtOTY5MC1kY2ZlMmI0ZThjMzEiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMjEtMDUtMTVUMTA6NDU6MzguNDAwNTU0ODM0WiJ9" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" vars.name=postgres-analytics vars.uuid=3cf39aac-0431-498a-9690-dcfe2b4e8c31 
time="2021-05-15T10:45:38.978130818Z" level=debug msg="s3aws.GetContent("/docker/registry/v2/repositories/postgres-analytics/_uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31/startedat")" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=623c4531-ef4b-41a9-a34f-1cdfb8d1d673 http.request.method=PATCH http.request.remoteaddr="X.X.X.X:57146" http.request.uri="/v2/postgres-analytics/blobs/uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31?_state=5f1hDFZqA3hqPO031sZlqvdiV72Wlne6sqFkVf9ithl7Ik5hbWUiOiJzeW5hLXBvc3RncmVzLWFuYWx5dGljcyIsIlVVSUQiOiIzY2YzOWFhYy0wNDMxLTQ5OGEtOTY5MC1kY2ZlMmI0ZThjMzEiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMjEtMDUtMTVUMTA6NDU6MzguNDAwNTU0ODM0WiJ9" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" trace.duration=38.377375ms trace.file="/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).GetContent" trace.id=f125abdc-2dba-4fad-ae8c-1a664f759555 trace.line=95 vars.name=postgres-analytics vars.uuid=3cf39aac-0431-498a-9690-dcfe2b4e8c31 
time="2021-05-15T10:45:39.065933909Z" level=debug msg="s3aws.Writer("/docker/registry/v2/repositories/postgres-analytics/_uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31/data", true)" go.version=go1.11.2 http.request.host="registry.somedomain.com:15236" http.request.id=623c4531-ef4b-41a9-a34f-1cdfb8d1d673 http.request.method=PATCH http.request.remoteaddr="X.X.X.X:57146" http.request.uri="/v2/postgres-analytics/blobs/uploads/3cf39aac-0431-498a-9690-dcfe2b4e8c31?_state=5f1hDFZqA3hqPO031sZlqvdiV72Wlne6sqFkVf9ithl7Ik5hbWUiOiJzeW5hLXBvc3RncmVzLWFuYWx5dGljcyIsIlVVSUQiOiIzY2YzOWFhYy0wNDMxLTQ5OGEtOTY5MC1kY2ZlMmI0ZThjMzEiLCJPZmZzZXQiOjAsIlN0YXJ0ZWRBdCI6IjIwMjEtMDUtMTVUMTA6NDU6MzguNDAwNTU0ODM0WiJ9" http.request.useragent="docker/20.10.5 go/go1.13.15 git-commit/363e9a8 kernel/5.10.25-linuxkit os/linux arch/amd64 UpstreamClient(skaffold-v1.24.0)" trace.duration=87.742286ms trace.file="/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).Writer" trace.id=ea54e2ba-aa3a-4cef-a414-7a749b3def48 trace.line=142 vars.name=postgres-analytics vars.uuid=3cf39aac-0431-498a-9690-dcfe2b4e8c31
fabifrank commented 3 years ago

Test with docker standalone push revealed it is a network issue. Would be helpful if skaffold would display progress while pushing though. Skaffold only shows done steps:

Screenshot 2021-05-15 at 14 02 25