Internal error occurred: admission plugin "MutatingAdmissionWebhook" failed to complete mutation in 13s

[burrmit]

I am running into a problem ever since attempting to upgrade from version 2.7 to (i have tried 3.3/3.4/3.5) and getting the same results.

I think it might have something to do with my cosign validator, but not 100% sure.

After what appears to be a successful installation, connaisseur is properly denying images that do not match my policy that has been configured:
Error from server: admission webhook "connaisseur-svc.lab-connaisseur-ns.svc" denied the request: No matching policy rule could be found for image docker.io/library/redis:latest.

However, my images that should match the policy configured are just timing out:
Error from server (InternalError): Internal error occurred: admission plugin "MutatingAdmissionWebhook" failed to complete mutation in 13s

When looking through the logs I am seeing this error message (this is with version 3.3.0):

 "Traceback (most recent call last):  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 510, in wait_for    return await fut           ^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/subprocess.py\", line 199, in communicate
    stdin, stdout, stderr = await tasks.gather(stdin, stdout, stderr)
                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 375, in __wakeup
    future.result()
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 306, in __step_run_and_handle_result
    result = coro.throw(exc)
             ^^^^^^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/subprocess.py\", line 179, in _read_stream
    output = await stream.read()
             ^^^^^^^^^^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/streams.py\", line 688, in read
    block = await self.read(self._limit)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/streams.py\", line 695, in read
    await self._wait_for_data('read')
  File \"/usr/local/lib/python3.12/asyncio/streams.py\", line 527, in _wait_for_data
    await self._waiter
  File \"/usr/local/lib/python3.12/asyncio/futures.py\", line 287, in __await__
    yield self  # This tells Task to wait for completion.
    ^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 375, in __wakeup
    future.result()
  File \"/usr/local/lib/python3.12/asyncio/futures.py\", line 198, in result
    raise exc
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File \"/app/connaisseur/flask_application.py\", line 114, in __async_mutate
    response = await __admit(admission_request, session)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/flask_application.py\", line 146, in __admit
    await patches
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 375, in __wakeup
    future.result()
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 304, in __step_run_and_handle_result
    result = coro.send(None)
             ^^^^^^^^^^^^^^^
  File \"/app/connaisseur/flask_application.py\", line 241, in __validate_image
    trusted_digest = await validator.validate(image, **validator_arguments)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 79, in validate
    return CosignValidator.__apply_policy(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 391, in __apply_policy
    raise list(vals.values())[0][\"error\"]
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 135, in __validation_task
    values[\"digest\"] = await self.__get_cosign_validated_digests(image, values)
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 148, in __get_cosign_validated_digests
    returncode, stdout, stderr = await self.__validate_using_trust_root(
                                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 278, in __validate_using_trust_root
    return await self.__invoke_cosign(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File \"/app/connaisseur/validators/cosign/cosign_validator.py\", line 325, in __invoke_cosign
    stdout, stderr = await asyncio.wait_for(
                     ^^^^^^^^^^^^^^^^^^^^^^^
  File \"/usr/local/lib/python3.12/asyncio/tasks.py\", line 509, in wait_for
    async with timeouts.timeout(timeout):
  File \"/usr/local/lib/python3.12/asyncio/timeouts.py\", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError
", "taskName": "Task-107"

When running version 3.5.0 I see this in the logs for images that should match the policy:

{
  "level": "debug",
  "msg": "request body: {\"kind\":\"AdmissionReview\",\"apiVersion\":\"admission.k8s.io/v1\",\"request\":{\"uid\":\"6ee955a1-5968-499d-ad8e-5c2660a63cc8\",\"kind\":{\"group\":\"\",\"version\":\"v1\",\"kind\":\"Pod\"},\"resource\":{\"group\":\"\",\"version\":\"v1\",\"resource\":\"pods\"},\"requestKind\":{\"group\":\"\",\"version\":\"v1\",\"kind\":\"Pod\"},\"requestResource\":{\"group\":\"\",\"version\":\"v1\",\"resource\":\"pods\"},\"name\":\"test\",\"namespace\":\"mitchtest-ns\",\"operation\":\"CREATE\",\"userInfo\":{\"username\":\"name\",\"uid\":\"0cfae343-b8b7-4dc0-8fdd-b864fbadff86\",\"groups\":[\"group\",\"test-admins\",\"admin\",\"system:authenticated:oauth\",\"system:authenticated\"],\"extra\":{\"scopes.authorization.openshift.io\":[\"user:full\"]}},\"object\":{\"kind\":\"Pod\",\"apiVersion\":\"v1\",\"metadata\":{\"name\":\"test\",\"namespace\":\"test-ns\",\"creationTimestamp\":null,\"labels\":{\"run\":\"test\"},\"annotations\":{\"openshift.io/scc\":\"anyuid\"},\"managedFields\":[{\"manager\":\"kubectl-run\",\"operation\":\"Update\",\"apiVersion\":\"v1\",\"time\":\"2024-05-29T21:24:43Z\",\"fieldsType\":\"FieldsV1\",\"fieldsV1\":{\"f:metadata\":{\"f:labels\":{\".\":{},\"f:run\":{}}},\"f:spec\":{\"f:containers\":{\"k:{\\\"name\\\":\\\"test\\\"}\":{\".\":{},\"f:image\":{},\"f:imagePullPolicy\":{},\"f:name\":{},\"f:resources\":{},\"f:terminationMessagePath\":{},\"f:terminationMessagePolicy\":{}}},\"f:dnsPolicy\":{},\"f:enableServiceLinks\":{},\"f:restartPolicy\":{},\"f:schedulerName\":{},\"f:securityContext\":{},\"f:terminationGracePeriodSeconds\":{}}}}]},\"spec\":{\"volumes\":[{\"name\":\"kube-api-access\",\"projected\":{\"sources\":[{\"serviceAccountToken\":{\"expirationSeconds\":3607,\"path\":\"token\"}},{\"configMap\":{\"name\":\"kube-root-ca.crt\",\"items\":[{\"key\":\"ca.crt\",\"path\":\"ca.crt\"}]}},{\"downwardAPI\":{\"items\":[{\"path\":\"namespace\",\"fieldRef\":{\"apiVersion\":\"v1\",\"fieldPath\":\"metadata.namespace\"}}]}},{\"configMap\":{\"name\":\"openshift-service-ca.crt\",\"items\":[{\"key\":\"service-ca.crt\",\"path\":\"service-ca.crt\"}]}}],\"defaultMode\":420}}],\"containers\":[{\"name\":\"test\",\"image\":\"quay.prod-openshift.com/image/ibm-http-server:latest\",\"resources\":{},\"volumeMounts\":[{\"name\":\"kube-api-access-jnbmz\",\"readOnly\":true,\"mountPath\":\"/var/run/secrets/kubernetes.io/serviceaccount\"}],\"terminationMessagePath\":\"/dev/termination-log\",\"terminationMessagePolicy\":\"File\",\"imagePullPolicy\":\"Always\",\"securityContext\":{\"capabilities\":{\"drop\":[\"MKNOD\"]}}}],\"restartPolicy\":\"Always\",\"terminationGracePeriodSeconds\":30,\"dnsPolicy\":\"ClusterFirst\",\"serviceAccountName\":\"default\",\"serviceAccount\":\"default\",\"securityContext\":{\"seLinuxOptions\":{\"level\":\"s0:c30,c25\"}},\"imagePullSecrets\":[{\"name\":\"default-dockercfg-\"},{\"name\":\"default-quay\"}],\"schedulerName\":\"default-scheduler\",\"tolerations\":[{\"key\":\"node.kubernetes.io/not-ready\",\"operator\":\"Exists\",\"effect\":\"NoExecute\",\"tolerationSeconds\":300},{\"key\":\"node.kubernetes.io/unreachable\",\"operator\":\"Exists\",\"effect\":\"NoExecute\",\"tolerationSeconds\":300}],\"priority\":0,\"enableServiceLinks\":true,\"preemptionPolicy\":\"PreemptLowerPriority\"},\"status\":{}},\"oldObject\":null,\"dryRun\":false,\"options\":{\"kind\":\"CreateOptions\",\"apiVersion\":\"meta.k8s.io/v1\",\"fieldManager\":\"kubectl-run\"}}}\n",
  "time": "2024-05-29T21:24:43Z"
}
{
  "level": "debug",
  "msg": "matched rule: quay.prod-openshift.com/* for image quay.prod-openshift.com/image/ibm-http-server:latest with reqId %!s(\u003cnil\u003e)",
  "time": "2024-05-29T21:24:43Z"
}
{
  "level": "debug",
  "msg": "validator: quayprod",
  "time": "2024-05-29T21:24:43Z"
}
{
  "level": "debug",
  "msg": "parent container images: []",
  "time": "2024-05-29T21:24:43Z"
}
{
  "level": "debug",
  "msg": "error getting cached digest: cache miss for image quay.prod-openshift.com/image/ibm-http-server:latest: cache disabled",
  "time": "2024-05-29T21:24:43Z"
}

Both version throw the same failed to complete mutation and not sure what I am missing.

here is a redacted version of my values.yml

kubernetes:
  deployment:
    envs: {}
    image:
      repository: quay.prod-openshift.com/image/connaisseur
    replicasCount: 1
    resources:
      limits:
        cpu: 1000m
        memory: 1Gi
      requests:
        cpu: 500m
        memory: 512Mi
    securityContext:
      runAsGroup: null
      runAsUser: null
  service:
    type: ClusterIP
    port: 443
  ingress:
    className: nginx-ingress
  webhook:
    failurePolicy: Fail # use 'Ignore' to fail open if Connaisseur becomes unavailable
    reinvocationPolicy: Never

application:
  logLevel: DEBUG
  validators:
    - name: quayprod
      type: cosign
      trustRoots:
      - name: default
        key: |
          -----BEGIN PUBLIC KEY-----

          -----END PUBLIC KEY-----
      cert: |
        -----BEGIN CERTIFICATE-----

        -----END CERTIFICATE-----
  policy:
  - pattern: "quay.prod-openshift.com/*"
    validator: quayprod
  features:
    detectionMode: false
    automaticChildApproval: true
    automaticUnchangedApproval: false
    namespacedValidation:
      mode: validate
    cache:
      expirySeconds: 0
      cacheErrors: false

So I believe I have narrowed it down now more, and it looks to be related to certificates; however, the cert section in the values file was working just fine in previous version of Connaisseur, and now it seems to not be validating the same certificate that as not changed, in the later versions.

Error being seen now after turning off the verifyInTransparencyLog: false flag (required because we are using Cosign 1.0 for signing, is this:

{
  "level": "debug",
  "msg": "validator: quayprod",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "parent container images: []",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "error getting cached digest: cache miss for image quay.prod-openshift.com/image/my-site:latest: redis: nil",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "validating image quay.prod-openshift.com/image/my-site:latest with trust root default",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "2024/05/30 17:38:20 --\u003e GET https://quay.prod-openshift.com/v2/\n",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "2024/05/30 17:38:20 GET /v2/ HTTP/1.1\r\nHost: quay.prod-openshift.com\r\nUser-Agent: cosign/devel (linux; amd64) go-containerregistry/v0.19.1\r\nAccept-Encoding: gzip\r\n\r\n\n",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "2024/05/30 17:38:20 \u003c-- tls: failed to verify certificate: x509: certificate signed by unknown authority GET https://quay.prod-openshift.com/v2/ (84.011214ms)\n",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "error verifying signatures with verifier for trust root default: Get \"https://quay.prod-openshift.com/v2/\": tls: failed to verify certificate: x509: certificate signed by unknown authority",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "debug",
  "msg": "num signatures: 0/1 by validating trust root names: []",
  "time": "2024-05-30T17:38:20Z"
}
{
  "level": "error",
  "msg": "error validating Pod test: error during cosign validation of image quay.prod-openshift.com/image/my-site:latest: no signed digests",
  "time": "2024-05-30T17:38:20Z"
}

[Starkteetje]

hi @burrmit
it does indeed not work as intended. That the secret isn't created is intended in that we pass the certificate here to the registry's TLSClientConfig instead of overwriting the system certificate store via SSL_CERT_FILE. We could do that in our older Python version as we only called Cosign as a binary externally, now that Connaisseur is running on Golang, too, this would otherwise override the cert pool for each request.

I haven't looked deeply into why setting the TLSClientConfig doesn't work, but will investigate further. Thanks for raising the issue