Internal server serror when using admission hook with an existing invalid resource

[tahajahangir]

Long story short

Steps to reproduce:

1. Apply an invalid object (e.g. when operator is stopped, and ValidatingWebhookConfiguration is not present)

kubectl apply -f https://github.com/nolar/kopf/blob/main/examples/crd.yaml
kubectl apply -f https://github.com/nolar/kopf/blob/main/examples/obj.yaml

2. Run the attached kopf code (simple admission webhook) (host of WebhookServer should be modified base on environemnt)

kopf run kopf_test.py --all-namespaces

3. The server enters a retry loop, and prints an error after 10 retries.

Kopf version

1.35.3

Kubernetes version

v1.20.13

Python version

3.10.1

Code

import kopf


@kopf.on.resume('kopfexamples')
def resume(**kwargs):
    print(kwargs)


@kopf.on.validate('kopfexamples')
def validate1(spec, dryrun, **_):
    print(f'{dryrun=}')
    if spec.get('field') == 'value':
        raise kopf.AdmissionError("Meh! I don't like it. Change the field.")


@kopf.on.startup()
def configure(settings: kopf.OperatorSettings, **_):
    settings.admission.managed = 'auto.kopf.dev'
    settings.admission.server = kopf.WebhookServer(addr='0.0.0.0', port=7100, host='127.0.0.1')

Logs

[2022-01-01 14:06:54,586] kopf.activities.auth [INFO    ] Activity 'login_via_pykube' succeeded.
[2022-01-01 14:06:54,598] kopf.activities.auth [INFO    ] Activity 'login_via_client' succeeded.
[2022-01-01 14:06:54,598] kopf._core.engines.a [INFO    ] Initial authentication has finished.
[2022-01-01 14:06:56,494] kopf._core.engines.a [INFO    ] Reconfiguring the validating webhook auto.kopf.dev.
[2022-01-01 14:06:56,575] kopf._core.engines.a [INFO    ] Reconfiguring the mutating webhook auto.kopf.dev.
dryrun=False
[2022-01-01 14:06:56,794] kopf.objects         [ERROR   ] [default/kopf-example-1] Webhook 'validate1' failed permanently: Meh! I don't like it. Change the field.
[2022-01-01 14:06:56,795] aiohttp.access       [INFO    ] 127.0.0.1 [01/Jan/2022:10:36:56 +0000] "POST /validate1?timeout=30s HTTP/1.1" 200 381 "-" "kube-apiserver-admission"
[2022-01-01 14:06:56,886] kopf.objects         [ERROR   ] [default/kopf-example-1] Request attempt #1/9 failed; will retry: PATCH https://cluster.local/apis/zalando.org/v1/namespaces/default/kopfexamples/kopf-example-1 -> APIServerError('admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', {'kind': 'Status', 'apiVersion': 'v1', 'metadata': {}, 'status': 'Failure', 'message': 'admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', 'code': 500})
dryrun=False
[2022-01-01 14:06:57,941] kopf.objects         [ERROR   ] [default/kopf-example-1] Webhook 'validate1' failed permanently: Meh! I don't like it. Change the field.
[2022-01-01 14:06:57,942] aiohttp.access       [INFO    ] 127.0.0.1 [01/Jan/2022:10:36:57 +0000] "POST /validate1?timeout=30s HTTP/1.1" 200 381 "-" "kube-apiserver-admission"
[2022-01-01 14:06:57,991] kopf.objects         [ERROR   ] [default/kopf-example-1] Request attempt #2/9 failed; will retry: PATCH https://cluster.local/apis/zalando.org/v1/namespaces/default/kopfexamples/kopf-example-1 -> APIServerError('admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', {'kind': 'Status', 'apiVersion': 'v1', 'metadata': {}, 'status': 'Failure', 'message': 'admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', 'code': 500})

....

dryrun=False
[2022-01-01 14:07:52,512] kopf.objects         [ERROR   ] [default/kopf-example-1] Webhook 'validate1' failed permanently: Meh! I don't like it. Change the field.
[2022-01-01 14:07:52,514] aiohttp.access       [INFO    ] 127.0.0.1 [01/Jan/2022:10:37:52 +0000] "POST /validate1?timeout=30s HTTP/1.1" 200 381 "-" "kube-apiserver-admission"
[2022-01-01 14:07:52,579] kopf.objects         [ERROR   ] [default/kopf-example-1] Request attempt #9/9 failed; escalating: PATCH https://cluster.local/apis/zalando.org/v1/namespaces/default/kopfexamples/kopf-example-1 -> APIServerError('admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', {'kind': 'Status', 'apiVersion': 'v1', 'metadata': {}, 'status': 'Failure', 'message': 'admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', 'code': 500})
[2022-01-01 14:07:52,580] kopf.objects         [ERROR   ] [default/kopf-example-1] Throttling for 1 seconds due to an unexpected error: APIServerError('admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', {'kind': 'Status', 'apiVersion': 'v1', 'metadata': {}, 'status': 'Failure', 'message': 'admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', 'code': 500})
Traceback (most recent call last):
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/errors.py", line 148, in check_response
    response.raise_for_status()
  File "/virtualenvs/temp/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 1004, in raise_for_status
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 500, message='Internal Server Error', url=URL('https://cluster.local/apis/zalando.org/v1/namespaces/default/kopfexamples/kopf-example-1')

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

Traceback (most recent call last):
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_core/actions/throttlers.py", line 44, in throttled
    yield should_run
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_core/reactor/processing.py", line 130, in process_resource_event
    applied = await application.apply(
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_core/actions/application.py", line 60, in apply
    await patch_and_check(
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_core/actions/application.py", line 131, in patch_and_check
    resulting_body = await patching.patch_obj(
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/patching.py", line 47, in patch_obj
    patched_body = await api.patch(
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/api.py", line 155, in patch
    response = await request(
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/auth.py", line 45, in wrapper
    return await fn(*args, **kwargs, context=context)
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/api.py", line 85, in request
    await errors.check_response(response)  # but do not parse it!
  File "/virtualenvs/temp/lib/python3.10/site-packages/kopf/_cogs/clients/errors.py", line 150, in check_response
    raise cls(payload, status=response.status) from e
kopf._cogs.clients.errors.APIServerError: ('admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', {'kind': 'Status', 'apiVersion': 'v1', 'metadata': {}, 'status': 'Failure', 'message': 'admission webhook "validate1.auto.kopf.dev" denied the request: Meh! I don\'t like it. Change the field.', 'code': 500})

Additional information

No response

[nolar]

Thanks for reporting. It is an interesting case: every component behaves properly as expected, but together they misbehave.

What would be the expected behaviour in this case?

[tahajahangir]

Kopf tries to updated the last-handled-configuration annotation, but the update fails with server-error. I think kopf should recognize the admission web hook .... denied the request errors and 1) stop retrying 2) logging this with warning (not error) level (since this is a user error, not an app error)