skaffold icon indicating copy to clipboard operation
skaffold copied to clipboard
verified publisher icon GoogleContainerTools

After-deploy hooks: Only the first `container` hook executes

Open halvards opened this issue 3 years ago • 3 comments

Expected behavior

All the container hooks in the deploy.kubectl.hooks.after section of skaffold.yaml should execute - at least as long as each previous hook exits with a zero exit status.

Actual behavior

Only the first container hook executes.

Information

  • Skaffold version: v2.1.0
  • Operating system: Linux (Debian)
  • Installed via: Download from GitHub Releases page
  • Contents of skaffold.yaml:
apiVersion: skaffold/v4beta2
kind: Config
build:
  artifacts:
  - image: repro
    ko:
      fromImage: gcr.io/distroless/base-debian11:debug-nonroot
manifests:
  rawYaml:
  - k8s/*.yaml
deploy:
  kubectl:
    hooks:
      after:
      - container:
          command: ["echo", "container-hook-0"]
          containerName: test
          podName: repro*
      - container:
          command: ["echo", "container-hook-1"]
          containerName: test
          podName: repro*
      - host:
          command: ["./hack/after-deploy-hook.sh"]
          os: [darwin, linux]
      - host:
          command: ["echo", "host-hook-1"]
          os: [darwin, linux]

Steps to reproduce the behavior

  1. git clone https://github.com/halvards/repro-skaffold-hooks.git
  2. cd repro-skaffold-hooks
  3. git checkout 54f9a42e59bb18c2adfce6c12b541bec28e7d0f7
  4. skaffold run

Output of skaffold run -vdebug. There is no mention of container-hook-1:

time="2023-01-24T13:32:32+11:00" level=debug msg="skaffold API not starting as it's not requested" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=info msg="Skaffold &{Version:v2.1.0 ConfigVersion:skaffold/v4beta2 GitVersion: GitCommit:c037d6f51276e178a2c05c1c59665956ff34aa4c BuildDate:2023-01-23T09:57:08Z GoVersion:go1.19.1 Compiler:gc Platform:linux/amd64 User:}" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="Skipping update check for flag `--update-check` set to false" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=info msg="Loaded Skaffold defaults from \"/home/username/.skaffold/config\"" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="parsed 1 configs from configuration file /home/username/repro-skaffold-hooks/skaffold.yaml" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="Defaulting build type to local build" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=info msg="map entry found when executing locate for &{repro . <nil> {<nil> <nil> 0xc000b52000 <nil> <nil> <nil> <nil>} [] {[] []} [] } of type *latest.Artifact and pointer: 824645194000" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="skipping validating `kubectl` deployer manifests since only the default manifest list is defined" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=info msg="Using kubectl context: minikube" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:32+11:00" level=debug msg="Running command: [minikube version --output=json]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: [{\"commit\":\"986b1ebd987211ed16f8cc10aed7d2c42fc8392f\",\"minikubeVersion\":\"v1.28.0\"}\n]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [/usr/bin/minikube docker-env --shell none -p minikube --user=skaffold]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: [DOCKER_TLS_VERIFY=1\nDOCKER_HOST=tcp://192.168.49.2:2376\nDOCKER_CERT_PATH=/home/username/.minikube/certs\nMINIKUBE_ACTIVE_DOCKERD=minikube\n]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="setting Docker user agent to skaffold-v2.1.0" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=info msg="Using minikube docker daemon at tcp://192.168.49.2:2376" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=info msg="no kpt renderer or deployer found, skipping hydrated-dir creation" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [kubectl config view --minify -o jsonpath='{..namespace}']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: ['default']" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="CLI platforms provided: \"\"" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="platforms detected from active kubernetes cluster nodes: \"linux/amd64\"" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="platforms selected for artifact \"repro\": \"linux/amd64\"" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="Using builder: local" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=debug msg="push value not present in NewBuilder, defaulting to false because cluster.PushImages is false" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=info msg="build concurrency first set to 1 parsed from *local.Builder[0]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:33+11:00" level=info msg="final build concurrency value is 1" subtask=-1 task=DevLoop
Generating tags...
 - repro -> time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [git describe --tags --always]" subtask=-1 task=Build
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: [ddad022\n]" subtask=-1 task=Build
time="2023-01-24T13:32:33+11:00" level=debug msg="Running command: [git status . --porcelain]" subtask=-1 task=Build
time="2023-01-24T13:32:33+11:00" level=debug msg="Command output: [?? log.txt\n]" subtask=-1 task=Build
repro:ddad022-dirty
time="2023-01-24T13:32:33+11:00" level=info msg="Tags generated in 9.142322ms" subtask=-1 task=Build
Checking cache...
time="2023-01-24T13:32:33+11:00" level=debug msg="push value not present in isImageLocal(), defaulting to false because cluster.PushImages is false" subtask=-1 task=DevLoop
 - repro: Found. Tagging
time="2023-01-24T13:32:34+11:00" level=debug msg="push value not present in isImageLocal(), defaulting to false because cluster.PushImages is false" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=info msg="Cache check completed in 38.670567ms" subtask=-1 task=Build
Starting test...
time="2023-01-24T13:32:34+11:00" level=info msg="Test completed in 19.922µs" subtask=-1 task=Test
time="2023-01-24T13:32:34+11:00" level=info msg="Starting render..." subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=info msg="starting render process" subtask=0 task=Render
time="2023-01-24T13:32:34+11:00" level=debug msg="Executing template &{envTemplate 0xc000774c60 0xc0005ee140  } with environment map[REDACTED]" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="manifests with tagged images:apiVersion: apps/v1\nkind: Deployment\nmetadata:\n  name: repro\nspec:\n  selector:\n    matchLabels:\n      app: repro\n  template:\n    metadata:\n      labels:\n        app: repro\n    spec:\n      containers:\n      - image: repro:dd842bde1ab4e948034d71f2ce46e9b4163cde726ebc88196c0acd44499ea4f9\n        name: test\n        ports:\n        - containerPort: 8080\n---\napiVersion: v1\nkind: Namespace\nmetadata:\n  name: test" subtask=0 task=Render
time="2023-01-24T13:32:34+11:00" level=debug msg="manifests with labels apiVersion: apps/v1\nkind: Deployment\nmetadata:\n  labels:\n    skaffold.dev/run-id: e994db1a-c703-4a83-a512-a21b6c570cc2\n  name: repro\nspec:\n  selector:\n    matchLabels:\n      app: repro\n  template:\n    metadata:\n      labels:\n        app: repro\n        skaffold.dev/run-id: e994db1a-c703-4a83-a512-a21b6c570cc2\n    spec:\n      containers:\n      - image: repro:dd842bde1ab4e948034d71f2ce46e9b4163cde726ebc88196c0acd44499ea4f9\n        name: test\n        ports:\n        - containerPort: 8080\n---\napiVersion: v1\nkind: Namespace\nmetadata:\n  name: test" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="manifests set with namespace apiVersion: apps/v1\nkind: Deployment\nmetadata:\n  labels:\n    skaffold.dev/run-id: e994db1a-c703-4a83-a512-a21b6c570cc2\n  name: repro\n  namespace: default\nspec:\n  selector:\n    matchLabels:\n      app: repro\n  template:\n    metadata:\n      labels:\n        app: repro\n        skaffold.dev/run-id: e994db1a-c703-4a83-a512-a21b6c570cc2\n    spec:\n      containers:\n      - image: repro:dd842bde1ab4e948034d71f2ce46e9b4163cde726ebc88196c0acd44499ea4f9\n        name: test\n        ports:\n        - containerPort: 8080\n---\napiVersion: v1\nkind: Namespace\nmetadata:\n  name: test" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=info msg="Render completed in 1.503721ms" subtask=-1 task=DevLoop
Tags used in deployment:
 - repro -> repro:dd842bde1ab4e948034d71f2ce46e9b4163cde726ebc88196c0acd44499ea4f9
time="2023-01-24T13:32:34+11:00" level=debug msg="push value not present in isImageLocal(), defaulting to false because cluster.PushImages is false" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="Local images can't be referenced by digest.\nThey are tagged and referenced by a unique, local only, tag instead.\nSee https://skaffold.dev/docs/pipeline-stages/taggers/#how-tagging-works" subtask=-1 task=Deploy
Starting deploy...
time="2023-01-24T13:32:34+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="Running command: [kubectl --context minikube get -f - --ignore-not-found -ojson]" subtask=0 task=Deploy
time="2023-01-24T13:32:34+11:00" level=debug msg="Command output: []" subtask=0 task=Deploy
time="2023-01-24T13:32:34+11:00" level=debug msg="2 manifests to deploy. 2 are updated or new" subtask=0 task=Deploy
time="2023-01-24T13:32:34+11:00" level=debug msg="Running command: [kubectl --context minikube apply -f -]" subtask=0 task=Deploy
 - deployment.apps/repro created
 - namespace/test created
Waiting for deployments to stabilize...
time="2023-01-24T13:32:34+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:34+11:00" level=debug msg="checking status deployment/repro" subtask=0 task=Deploy
time="2023-01-24T13:32:35+11:00" level=debug msg="Running command: [kubectl --context minikube rollout status deployment repro --namespace default --watch=false]" subtask=0 task=Deploy
time="2023-01-24T13:32:35+11:00" level=debug msg="Command output: [Waiting for deployment \"repro\" rollout to finish: 0 of 1 updated replicas are available...\n]" subtask=0 task=Deploy
time="2023-01-24T13:32:35+11:00" level=debug msg="Pod \"repro-6565f7bc6c-rqps8\" scheduled but not ready: checking container statuses" subtask=-1 task=DevLoop
time="2023-01-24T13:32:36+11:00" level=debug msg="Running command: [kubectl --context minikube rollout status deployment repro --namespace default --watch=false]" subtask=0 task=Deploy
time="2023-01-24T13:32:36+11:00" level=debug msg="Command output: [deployment \"repro\" successfully rolled out\n]" subtask=0 task=Deploy
 - deployment/repro is ready.
Deployments stabilized in 2.138 seconds
Starting post-deploy hooks...
time="2023-01-24T13:32:36+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:36+11:00" level=debug msg="Running command: [kubectl --context minikube exec repro-6565f7bc6c-rqps8 --namespace default -c test -- echo container-hook-0]" subtask=0 task=Deploy
[test]container-hook-0
time="2023-01-24T13:32:36+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
time="2023-01-24T13:32:36+11:00" level=debug msg="Running command: [./hack/after-deploy-hook.sh]" subtask=0 task=Deploy
SKAFFOLD_DEFAULT_REPO=
SKAFFOLD_HTTP_PORT=
SKAFFOLD_KUBE_CONTEXT=minikube
SKAFFOLD_MULTI_LEVEL_REPO=
SKAFFOLD_NAMESPACES=default
SKAFFOLD_RPC_PORT=
SKAFFOLD_RUN_ID=e994db1a-c703-4a83-a512-a21b6c570cc2
time="2023-01-24T13:32:36+11:00" level=debug msg="Running command: [echo host-hook-1]" subtask=0 task=Deploy
host-hook-1
Completed post-deploy hooks
time="2023-01-24T13:32:36+11:00" level=info msg="Deploy completed in 2.606 seconds" subtask=-1 task=Deploy
time="2023-01-24T13:32:36+11:00" level=debug msg="getting client config for kubeContext: `minikube`" subtask=-1 task=DevLoop
You can also run [skaffold run --tail] to get the logs

halvards avatar Jan 24 '23 02:01 halvards

The cause is that filterContainersSelector is used to determine if we should run a hook from a deployer, this filter is stateful with The combination of podName, containerName, phase as key to determine if a hook should run. The problem is that if the selector will believe that a hook has already been executed if the container and podName are same with same phase when users have multiple hooks with the same container only one is executed. It seems that we can use a stateless filter like NamePatternSelector to do a simply name matching to determine if a deployer should run a hook for the reason here. However, the assumption is not true, kubectl apply doesn't always recreate pods, for example, we have a whole bunch of resources in a single manifest, only one resource has changes -- like container image. If we uses stateless filter, hooks will always run regardless if it's associated resource is re-deployed or not. The same could happen to helm deployer as well, when using it to install multiple releases or some releases have many resources. Alternatively, we may add the index from hooks slice as part of key for fitlerPatternSelector, like (podName, containerName, phase, 1), (podName, containerName, phase, 2), so the same container won't be filtered out.

ericzzzzzzz avatar Jul 20 '23 11:07 ericzzzzzzz

Is there an argument to be made that hooks should also be distributed to the specific resources that they apply to? For instance, this would allow resources that were redeployed to have their hooks easily re-run.

This would solve a case (such as Vault via Helm) where subsequent installs that depend on Vault will fail if Vault does not report readiness. The only way to ready Vault is to run some script that inits and unseals the vault.

briantopping avatar May 26 '24 18:05 briantopping

Is there any update on this? we also have a use case where we need to run multiple hooks and this behavior is not allowing us to do so.

dmavrommatis avatar Oct 14 '24 16:10 dmavrommatis