[Need help] Ratify operation failed with error operation timed out after duration 1.95s

[FeynmanZhou]

I have a Minikube Kubernetes cluster (v1.25) running on my Ubuntu machine. Then I use Notation RC.2 to sign a sample image and generate a signature. It returned the following error log after I installed Ratify RC.1 and ran a signed sample image on my minikube cluster. I am wondering how to resolve the timeout problem.

$ kubectl run demo --image=localhost:5000/net-monitor-ratify:v1
Error from server: admission webhook "mutation.gatekeeper.sh" denied the request: failed to resolve external data placeholders: failed to validate external data response from provider ratify-mutation-provider: non-empty system error: operation failed with error operation timed out after duration 1.95s

My gatekeeper was installed by following the Ratify README and my Ratify installation script is as follows:

helm install ratify \
ce gatekeeper-sy> ratify/ratify --atomic \
>     --namespace gatekeeper-system \
>     --set-file provider.tls.crt=${CERT_DIR}/server.crt \
>     --set-file provider.tls.key=${CERT_DIR}/server.key \
>     --set-file ratifyTestCert="/home/azureuser/.config/notation/truststore/x509/ca/ratify-networks.io/ratify-networks.
io.crt" \
>     --set oras.useHttp=true \
>     --set provider.tls.cabundle="$(cat ${CERT_DIR}/ca.crt |base64 |tr -d '\n')"

[susanshi]

Hi @akashsinghal , have you seen this ratify-mutation-provider error before? From a debugging perspective, which logs would be relevant to review to understand which call timed out?

[susanshi]

Given this is a timeout, i wonder if you increase the timeout ( maybe try 3) --set mutatingWebhookTimeoutSeconds=2 , will the request complete. But of course, if the call doesn't not complete in 2sec, Ratify team need to review the perf requirements.

[akashsinghal]

@FeynmanZhou would it be possible for you to enable debug logs, reinstall ratify in the cluster, and then upload your logs here? That will really help pinpoint which operation is stuck. You can add an extra flag to the helm install command for ratify: --set logLevel=debug.

I have only seen timeouts a handful of times when doing many benchmark tests with the AKS + workload identity scenario. It was very rare. This is a local registry so there shouldn't be much latency. In fact we use a kind cluster with a local registry for our e2e tests too.

Also, could we get a bit more information on how you are running the local registry?

[FeynmanZhou]

@akashsinghal @susanshi Thank you. I ran the local registry using the
distribution.

After I reinstalled the Ratify helm chart with --set logLevel=debug, I got the following logs from the Ratify Pod as follows:

 kubectl logs ratify-5fc4fbcd56-tll2w -n gatekeeper-system
time="2023-02-15T04:06:05Z" level=info msg="Setting log level to debug"
time="2023-02-15T04:06:05Z" level=info msg="starting crd manager"
time="2023-02-15T04:06:05Z" level=info msg="initializing executor with config file at default config path"
time="2023-02-15T04:06:05Z" level=info msg="selected default auth provider: dockerConfig"
time="2023-02-15T04:06:05Z" level=info msg="stores successfully created. number of stores 1"
time="2023-02-15T04:06:05Z" level=info msg="defaultPluginPath set to /.ratify/plugins"
time="2023-02-15T04:06:05Z" level=info msg="verifiers successfully created. number of verifiers 2"
time="2023-02-15T04:06:05Z" level=info msg="selected policy provider: configPolicy"
time="2023-02-15T04:06:05Z" level=info msg="policies successfully created."
time="2023-02-15T04:06:05Z" level=info msg="starting server at:6001"
time="2023-02-15T04:06:05Z" level=info msg="starting server using TLS: [certFile:/usr/local/tls/tls.crt] [keyFile:/usr/local/tls/tls.key]"
time="2023-02-15T04:06:05Z" level=info msg="loaded client CA certificate for mTLS: [CaFIle:usr/local/tls/client-ca/ca.crt] "
1.6764339657648878e+09  INFO    controller-runtime.metrics      Metrics server is starting to listen    {"addr": ":8080"}
time="2023-02-15T04:06:05Z" level=info msg="starting manager" name=setup
1.6764339657669556e+09  INFO    Starting server {"path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
1.6764339657671418e+09  INFO    Starting server {"kind": "health probe", "addr": "[::]:8081"}
1.6764339657673254e+09  INFO    Starting EventSource    {"controller": "verifier", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Verifier", "source": "kind source: *v1alpha1.Verifier"}
1.676433965767357e+09   INFO    Starting Controller     {"controller": "verifier", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Verifier"}
1.6764339657676163e+09  INFO    Starting EventSource    {"controller": "certificatestore", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "CertificateStore", "source": "kind source: *v1alpha1.CertificateStore"}
1.6764339657676444e+09  INFO    Starting Controller     {"controller": "certificatestore", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "CertificateStore"}
1.6764339657679775e+09  INFO    Starting EventSource    {"controller": "store", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Store", "source": "kind source: *v1alpha1.Store"}
1.6764339657680163e+09  INFO    Starting Controller     {"controller": "store", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Store"}
1.6764339658685803e+09  INFO    Starting workers        {"controller": "store", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Store", "worker count": 1}
1.676433965868612e+09   INFO    Starting workers        {"controller": "certificatestore", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "CertificateStore", "worker count": 1}
1.6764339658686533e+09  INFO    Starting workers        {"controller": "verifier", "controllerGroup": "config.ratify.deislabs.io", "controllerKind": "Verifier", "worker count": 1}
time="2023-02-15T04:06:05Z" level=info msg="reconciling verifier 'verifier-cosign'"
time="2023-02-15T04:06:05Z" level=info msg="Address was empty, setting to default path: /.ratify/plugins"
time="2023-02-15T04:06:05Z" level=info msg="verifier 'cosign' added to verifier map"
time="2023-02-15T04:06:05Z" level=info msg="reconciling verifier 'verifier-notary'"
time="2023-02-15T04:06:05Z" level=info msg="Address was empty, setting to default path: /.ratify/plugins"
time="2023-02-15T04:06:05Z" level=info msg="reconciling store 'store-oras'"
time="2023-02-15T04:06:05Z" level=info msg="verifier 'notaryv2' added to verifier map"
time="2023-02-15T04:06:05Z" level=info msg="Address was empty, setting to default path /.ratify/plugins"
time="2023-02-15T04:06:05Z" level=info msg="selected default auth provider: dockerConfig"
time="2023-02-15T04:06:05Z" level=info msg="store 'oras' added to store map"
time="2023-02-15T04:06:05Z" level=info msg="reconciling store 'store-orask8secret'"
time="2023-02-15T04:06:05Z" level=info msg="Address was empty, setting to default path /.ratify/plugins"
time="2023-02-15T04:06:05Z" level=info msg="selected auth provider: dockerConfig"
time="2023-02-15T04:06:05Z" level=info msg="store 'oras' added to store map"
time="2023-02-15T04:06:14Z" level=info msg="received request POST /ratify/gatekeeper/v1/verify "
time="2023-02-15T04:06:14Z" level=info msg="start request POST /ratify/gatekeeper/v1/verify"
time="2023-02-15T04:06:14Z" level=info msg="verifying subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:06:14Z" level=debug msg="cache miss for subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:06:14Z" level=debug msg="no digest provided for reference wabbitnetworks.azurecr.io/test/net-monitor:signed. attempting to resolve..."
time="2023-02-15T04:06:14Z" level=debug msg="performing request method HEAD url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/manifests/signed"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/oauth2/token?scope=repository%3Atest%2Fnet-monitor%3Apull&service=wabbitnetworks.azurecr.io"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method HEAD url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/manifests/signed"
time="2023-02-15T04:06:14Z" level=info msg="Resolve of the image completed successfully the digest is sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/referrers/sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/referrers/sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/oauth2/token?scope=repository%3Atest%2Fnet-monitor%3Apull&service=wabbitnetworks.azurecr.io"
time="2023-02-15T04:06:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/referrers/sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
{
  "isSuccess": false,
  "verifierReports": [
    {
      "subject": "wabbitnetworks.azurecr.io/test/net-monitor:signed",
      "isSuccess": false,
      "message": "verification failed: no referrers found for this artifact"
    }
  ]
}
time="2023-02-15T04:06:14Z" level=debug msg="verification: execution time for image wabbitnetworks.azurecr.io/test/net-monitor:signed: 304ms"
time="2023-02-15T04:06:14Z" level=debug msg="verification: execution time for request: 304ms"
time="2023-02-15T04:06:14Z" level=info msg="received request POST /ratify/gatekeeper/v1/verify "
time="2023-02-15T04:06:14Z" level=info msg="start request POST /ratify/gatekeeper/v1/verify"
time="2023-02-15T04:06:14Z" level=info msg="verifying subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:06:14Z" level=debug msg="cache hit for subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:06:14Z" level=debug msg="verification: execution time for image wabbitnetworks.azurecr.io/test/net-monitor:signed: 0ms"
time="2023-02-15T04:06:14Z" level=debug msg="verification: execution time for request: 0ms"
time="2023-02-15T04:06:50Z" level=info msg="received request POST /ratify/gatekeeper/v1/mutate "
time="2023-02-15T04:06:50Z" level=info msg="start request POST /ratify/gatekeeper/v1/mutate"
time="2023-02-15T04:06:50Z" level=info msg="mutating image localhost:5000/net-monitor-ratify:v1"
time="2023-02-15T04:06:50Z" level=debug msg="no digest provided for reference localhost:5000/net-monitor-ratify:v1. attempting to resolve..."
time="2023-02-15T04:06:50Z" level=debug msg="performing request method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:50Z" level=error msg="request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:50Z" level=debug msg="retrying request request HEAD https://localhost:5000/v2/net-monitor-ratify/manifests/v1 timeout 148.533747ms remaining 10"
time="2023-02-15T04:06:51Z" level=error msg="request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:51Z" level=debug msg="retrying request request HEAD https://localhost:5000/v2/net-monitor-ratify/manifests/v1 timeout 213.105214ms remaining 9"
time="2023-02-15T04:06:51Z" level=error msg="request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:51Z" level=debug msg="retrying request request HEAD https://localhost:5000/v2/net-monitor-ratify/manifests/v1 timeout 478.134441ms remaining 8"
time="2023-02-15T04:06:51Z" level=error msg="request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:51Z" level=debug msg="retrying request request HEAD https://localhost:5000/v2/net-monitor-ratify/manifests/v1 timeout 623.5204ms remaining 7"
time="2023-02-15T04:06:52Z" level=error msg="request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1"
time="2023-02-15T04:06:52Z" level=debug msg="retrying request request HEAD https://localhost:5000/v2/net-monitor-ratify/manifests/v1 timeout 530.33309ms remaining 6"
time="2023-02-15T04:06:52Z" level=error msg="failed to mutate image reference localhost:5000/net-monitor-ratify:v1: Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": context deadline exceeded"
time="2023-02-15T04:06:52Z" level=debug msg="mutation: execution time for request: 1950ms"
2023/02/15 04:06:52 http: superfluous response.WriteHeader call from github.com/deislabs/ratify/httpserver.sendResponse (handlers.go:201)
time="2023-02-15T04:07:14Z" level=info msg="received request POST /ratify/gatekeeper/v1/verify "
time="2023-02-15T04:07:14Z" level=info msg="start request POST /ratify/gatekeeper/v1/verify"
time="2023-02-15T04:07:14Z" level=info msg="verifying subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:07:14Z" level=debug msg="cache miss for subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:07:14Z" level=debug msg="no digest provided for reference wabbitnetworks.azurecr.io/test/net-monitor:signed. attempting to resolve..."
time="2023-02-15T04:07:14Z" level=debug msg="performing request method HEAD url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/manifests/signed"
time="2023-02-15T04:07:14Z" level=info msg="Resolve of the image completed successfully the digest is sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:07:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/referrers/sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:07:14Z" level=debug msg="performing request method GET url https://wabbitnetworks.azurecr.io/v2/test/net-monitor/referrers/sha256:025d2eb332facf92e535098df700f3ed94b0c8fa2f901bf90b2e23a6d2b046cf"
time="2023-02-15T04:07:14Z" level=debug msg="verification: execution time for image wabbitnetworks.azurecr.io/test/net-monitor:signed: 85ms"
time="2023-02-15T04:07:14Z" level=debug msg="verification: execution time for request: 86ms"
{
  "isSuccess": false,
  "verifierReports": [
    {
      "subject": "wabbitnetworks.azurecr.io/test/net-monitor:signed",
      "isSuccess": false,
      "message": "verification failed: no referrers found for this artifact"
    }
  ]
}
time="2023-02-15T04:07:14Z" level=info msg="received request POST /ratify/gatekeeper/v1/verify "
time="2023-02-15T04:07:14Z" level=info msg="start request POST /ratify/gatekeeper/v1/verify"
time="2023-02-15T04:07:14Z" level=info msg="verifying subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:07:14Z" level=debug msg="cache hit for subject wabbitnetworks.azurecr.io/test/net-monitor:signed"
time="2023-02-15T04:07:14Z" level=debug msg="verification: execution time for image wabbitnetworks.azurecr.io/test/net-monitor:signed: 0ms"
time="2023-02-15T04:07:14Z" level=debug msg="verification: execution time for request: 0ms"

[akashsinghal]

@FeynmanZhou looks like Ratify cannot connect to the local registry: request failed error Head \"https://localhost:5000/v2/net-monitor-ratify/manifests/v1\": dial tcp 127.0.0.1:5000: connect: connection refused method HEAD url https://localhost:5000/v2/net-monitor-ratify/manifests/v1

I think the registry isn't accessible inside the cluster. I found this guide that might help to make sure the registry's container network is properly binded to the host for minikube: https://minikube.sigs.k8s.io/docs/handbook/registry/#docker-on-macos

You can also use a Kind cluster instead. In fact our e2e tests use this method. You can look at all the setup steps in the Makefile.

Here's where the registry is started: https://github.com/deislabs/ratify/blob/e8d62e9b3c1e4b5c0af9fee51f87fe0a465fc0b3/Makefile#L153
And here's where the container networks are connected: https://github.com/deislabs/ratify/blob/e8d62e9b3c1e4b5c0af9fee51f87fe0a465fc0b3/Makefile#L199