Update event lost and handler is not fired

[valen7in]

Long story short

I am implementing state machine with control via annotations. There are two handlers ("state machine handler") - first for catching state updates, processing current state and setting next state, second ("control handler") - for catching annotations update to set new state if necessary (setting new state in control handler is not required to reproduce bug). When state machine handler and control handler both are executed "concurrently" (to be precise - one after another in one handling cycle), it is possible that state changes not triggering state machine handler.

Kopf version

1.38.0

Kubernetes version

1.29.1

Python version

3.10

Code

import time
from typing import Tuple, Mapping

import kopf
from kubernetes.client import ApiException, CustomObjectsApi, ApiClient

# this helper method just loads kube config
from kube_config import load_kube_config

api_client: ApiClient | None = None

@kopf.on.startup(id='setup-k8s-client')
def setup_k8s_api_client(logger, **kwargs):
    load_kube_config(logger)
    global api_client
    api_client = ApiClient()


@kopf.on.cleanup(id='teardown-k8s-client')
def tear_down_k8s_api_client(**kwargs):
    global api_client
    api_client.close()


def patch_resource(name: str, namespace: str, patch: dict, logger):
    co_api: CustomObjectsApi = CustomObjectsApi(api_client)
    try:
        res = co_api.patch_namespaced_custom_object_status('project.dev', 'v1',
                                                                namespace, 'tests', name, patch)
        logger.info(f'{namespace}/{name} is patched')
        return res
    except ApiException as exc:
        if exc.status == 409:
            logger.info(f'Сode 409 on "{namespace}/{name}" patch, version conflict')
            raise kopf.TemporaryError(delay=10)
        raise kopf.TemporaryError(delay=5)


def set_state(name: str, namespace: str, resource: dict, state: str, logger):
    patch = {
        'status': {'state': state}
    }
    patch_resource(name, namespace, patch, logger)


def get_state(resource: dict):
    status = resource.get('status', {})
    state = status.get('state', 'A')
    return state


def state_is_changed(diff: Tuple[Tuple], logger, **_):
    state_changed = any(('status', 'state') == d[1] for d in diff)
    state_added = any(isinstance(d[3], Mapping) and 'state' in d[3] for d in diff)
    state_added = state_added or any(isinstance(d[3], Mapping) and 'status' in d[3] and 'state' in d[3]['status'] for d in diff)
    return state_changed or state_added


def state_is_not_changed(diff: Tuple[Tuple], logger, **_):
    return not state_is_changed(diff, logger, **_)


@kopf.on.update('project.dev', 'tests',
                field='status',
                when=state_is_changed)
@kopf.on.create('project.dev', 'tests',
                field='status',
                when=state_is_changed)
def on_state_changed(spec, name, namespace, body, runtime, logger, **_):
    state = get_state(body)

    logger.info(f'Processing state {state}')

    if state == 'A':
        time.sleep(5)
        new_state = 'B'
    elif state == 'B':
        new_state = 'C'
    else:
        logger.info(f'Terminal state {state}')
        return

    logger.info(f'Going to state {new_state}')
    set_state(name, namespace, body, new_state, logger)


def is_test_anno_set(diff: Tuple[Tuple], **_):
    anno_changed = any(('metadata', 'annotations', 'project.dev/test') == d[1] for d in diff)
    anno_added = any(isinstance(d[3], Mapping) and 'project.dev/test' in d[3] for d in diff)
    anno_dict_added = next(filter(lambda d: isinstance(d[3], Mapping) and 'annotations' in d[3], diff), None)
    if anno_dict_added:
        anno_added = anno_added or 'project.dev/test' in anno_dict_added
    return anno_changed or anno_added


@kopf.on.update('project.dev',
                'tests',
                field=f'metadata.annotations',                
                when=kopf.all_([is_test_anno_set]))
def on_test_anno_scheduling(spec, name, namespace, body, runtime, logger, **_):
    logger.info('on_test_anno_scheduling handler is called')

Logs

Short logs

[2025-07-27 19:24:51,070] kopf.activities.star [INFO    ] Sync load kubeconfig
[2025-07-27 19:24:51,078] kopf.activities.star [INFO    ] Client is configured via kubeconfig file.
[2025-07-27 19:24:51,079] kopf.activities.star [INFO    ] Activity 'setup-k8s-client' succeeded.
[2025-07-27 19:24:51,079] kopf._core.engines.a [INFO    ] Initial authentication has been initiated.
[2025-07-27 19:24:51,087] kopf.activities.auth [INFO    ] Activity 'login_via_client' succeeded.
[2025-07-27 19:24:51,087] kopf._core.engines.a [INFO    ] Initial authentication has finished.
[2025-07-27 19:25:17,197] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state A
[2025-07-27 19:25:22,204] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state B
[2025-07-27 19:25:22,308] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:25:22,309] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:25:22,309] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Creation is processed: 1 succeeded; 0 failed.
[2025-07-27 19:25:22,563] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state B
[2025-07-27 19:25:22,564] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state C
[2025-07-27 19:25:22,601] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:25:22,601] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:25:22,791] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] on_test_anno_scheduling handler is called
[2025-07-27 19:25:22,792] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_test_anno_scheduling/metadata.annotations' succeeded.
[2025-07-27 19:25:22,792] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Updating is processed: 2 succeeded; 0 failed.

It is clear, that "C" state is not processed. Verbose log shows what happens.

Verbose logs

[2025-07-27 19:26:54,013] kopf._core.reactor.r [DEBUG   ] Starting Kopf 1.38.0.
[2025-07-27 19:26:54,014] kopf.activities.star [DEBUG   ] Activity 'setup-k8s-client' is invoked.
[2025-07-27 19:26:54,014] kopf.activities.star [INFO    ] Sync load kubeconfig
[2025-07-27 19:26:54,023] kopf.activities.star [INFO    ] Client is configured via kubeconfig file.
[2025-07-27 19:26:54,023] kopf.activities.star [INFO    ] Activity 'setup-k8s-client' succeeded.
[2025-07-27 19:26:54,023] kopf._core.engines.a [INFO    ] Initial authentication has been initiated.
[2025-07-27 19:26:54,023] kopf.activities.auth [DEBUG   ] Activity 'login_via_client' is invoked.
[2025-07-27 19:26:54,033] kopf.activities.auth [DEBUG   ] Client is configured via kubeconfig file.
[2025-07-27 19:26:54,033] kopf.activities.auth [INFO    ] Activity 'login_via_client' succeeded.
[2025-07-27 19:26:54,033] kopf._core.engines.a [INFO    ] Initial authentication has finished.
[2025-07-27 19:26:54,226] kopf._cogs.clients.w [DEBUG   ] Starting the watch-stream for customresourcedefinitions.v1.apiextensions.k8s.io cluster-wide.
[2025-07-27 19:26:54,297] kopf._cogs.clients.w [DEBUG   ] Starting the watch-stream for namespaces.v1 cluster-wide.
[2025-07-27 19:26:54,297] kopf._cogs.clients.w [DEBUG   ] Starting the watch-stream for kopfpeerings.v1.kopf.dev in 'dev-kopf-state-event-loss'.
[2025-07-27 19:26:54,298] kopf._cogs.clients.w [DEBUG   ] Starting the watch-stream for tests.v1.project.dev in 'dev-kopf-state-event-loss'.
[2025-07-27 19:26:54,331] kopf._core.engines.p [DEBUG   ] Keep-alive in 'default' in 'dev-kopf-state-event-loss': not found.
[2025-07-27 19:27:20,986] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Creation is in progress: {'apiVersion': 'project.dev/v1', 'kind': 'Test', 'metadata': {'annotations': {'kubectl.kubernetes.io/last-applied-configuration': '{"apiVersion":"project.dev/v1","kind":"Test","metadata":{"annotations":{},"name":"test","namespace":"dev-kopf-state-event-loss"},"spec":{"key":"value"},"status":{"state":"A"}}\n'}, 'creationTimestamp': '2025-07-27T16:27:11Z', 'generation': 1, 'managedFields': [{'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'.': {}, 'f:kubectl.kubernetes.io/last-applied-configuration': {}}}, 'f:spec': {'.': {}, 'f:key': {}}}, 'manager': 'kubectl-client-side-apply', 'operation': 'Update', 'time': '2025-07-27T16:27:11Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {'.': {}, 'f:state': {}}}, 'manager': 'kubectl-patch', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:20Z'}], 'name': 'test', 'namespace': 'dev-kopf-state-event-loss', 'resourceVersion': '130813059', 'uid': '6eece680-c658-4567-9cbe-b053cbb66933'}, 'spec': {'key': 'value'}, 'status': {'state': 'A'}}
[2025-07-27 19:27:20,987] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' is invoked.
[2025-07-27 19:27:20,987] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state A
[2025-07-27 19:27:25,993] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state B
[2025-07-27 19:27:26,111] kubernetes.client.re [DEBUG   ] response body: {"apiVersion":"project.dev/v1","kind":"Test","metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"project.dev/v1\",\"kind\":\"Test\",\"metadata\":{\"annotations\":{},\"name\":\"test\",\"namespace\":\"dev-kopf-state-event-loss\"},\"spec\":{\"key\":\"value\"},\"status\":{\"state\":\"A\"}}\n","project.dev/test":"1"},"creationTimestamp":"2025-07-27T16:27:11Z","generation":1,"managedFields":[{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{".":{},"f:kubectl.kubernetes.io/last-applied-configuration":{}}},"f:spec":{".":{},"f:key":{}}},"manager":"kubectl-client-side-apply","operation":"Update","time":"2025-07-27T16:27:11Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:status":{}},"manager":"kubectl-patch","operation":"Update","subresource":"status","time":"2025-07-27T16:27:20Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{"f:project.dev/test":{}}}},"manager":"kubectl-patch","operation":"Update","time":"2025-07-27T16:27:21Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:status":{"f:state":{}}},"manager":"OpenAPI-Generator","operation":"Update","subresource":"status","time":"2025-07-27T16:27:26Z"}],"name":"test","namespace":"dev-kopf-state-event-loss","resourceVersion":"130813089","uid":"6eece680-c658-4567-9cbe-b053cbb66933"},"spec":{"key":"value"},"status":{"state":"B"}}

[2025-07-27 19:27:26,111] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:27:26,112] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:27:26,112] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Creation is processed: 1 succeeded; 0 failed.
[2025-07-27 19:27:26,112] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Patching with: {'metadata': {'annotations': {'kopf.zalando.org/last-handled-configuration': '{"spec":{"key":"value"},"metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\\"apiVersion\\":\\"project.dev/v1\\",\\"kind\\":\\"Test\\",\\"metadata\\":{\\"annotations\\":{},\\"name\\":\\"test\\",\\"namespace\\":\\"dev-kopf-state-event-loss\\"},\\"spec\\":{\\"key\\":\\"value\\"},\\"status\\":{\\"state\\":\\"A\\"}}\\n"}},"status":{"state":"A"}}\n'}}}
[2025-07-27 19:27:26,315] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating is in progress: {'apiVersion': 'project.dev/v1', 'kind': 'Test', 'metadata': {'annotations': {'kopf.zalando.org/last-handled-configuration': '{"spec":{"key":"value"},"metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\\"apiVersion\\":\\"project.dev/v1\\",\\"kind\\":\\"Test\\",\\"metadata\\":{\\"annotations\\":{},\\"name\\":\\"test\\",\\"namespace\\":\\"dev-kopf-state-event-loss\\"},\\"spec\\":{\\"key\\":\\"value\\"},\\"status\\":{\\"state\\":\\"A\\"}}\\n"}},"status":{"state":"A"}}\n', 'kubectl.kubernetes.io/last-applied-configuration': '{"apiVersion":"project.dev/v1","kind":"Test","metadata":{"annotations":{},"name":"test","namespace":"dev-kopf-state-event-loss"},"spec":{"key":"value"},"status":{"state":"A"}}\n', 'project.dev/test': '1'}, 'creationTimestamp': '2025-07-27T16:27:11Z', 'generation': 1, 'managedFields': [{'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'.': {}, 'f:kubectl.kubernetes.io/last-applied-configuration': {}}}, 'f:spec': {'.': {}, 'f:key': {}}}, 'manager': 'kubectl-client-side-apply', 'operation': 'Update', 'time': '2025-07-27T16:27:11Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {}}, 'manager': 'kubectl-patch', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:20Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'f:project.dev/test': {}}}}, 'manager': 'kubectl-patch', 'operation': 'Update', 'time': '2025-07-27T16:27:21Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {'f:state': {}}}, 'manager': 'OpenAPI-Generator', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:26Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'f:kopf.zalando.org/last-handled-configuration': {}}}}, 'manager': 'kopf', 'operation': 'Update', 'time': '2025-07-27T16:27:26Z'}], 'name': 'test', 'namespace': 'dev-kopf-state-event-loss', 'resourceVersion': '130813091', 'uid': '6eece680-c658-4567-9cbe-b053cbb66933'}, 'spec': {'key': 'value'}, 'status': {'state': 'B'}}
[2025-07-27 19:27:26,315] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating diff: (('change', ('status', 'state'), 'A', 'B'), ('add', ('metadata', 'annotations', 'project.dev/test'), None, '1'))
[2025-07-27 19:27:26,315] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' is invoked.
[2025-07-27 19:27:26,316] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state B
[2025-07-27 19:27:26,316] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state C
[2025-07-27 19:27:26,383] kubernetes.client.re [DEBUG   ] response body: {"apiVersion":"project.dev/v1","kind":"Test","metadata":{"annotations":{"kopf.zalando.org/last-handled-configuration":"{\"spec\":{\"key\":\"value\"},\"metadata\":{\"annotations\":{\"kubectl.kubernetes.io/last-applied-configuration\":\"{\\\"apiVersion\\\":\\\"project.dev/v1\\\",\\\"kind\\\":\\\"Test\\\",\\\"metadata\\\":{\\\"annotations\\\":{},\\\"name\\\":\\\"test\\\",\\\"namespace\\\":\\\"dev-kopf-state-event-loss\\\"},\\\"spec\\\":{\\\"key\\\":\\\"value\\\"},\\\"status\\\":{\\\"state\\\":\\\"A\\\"}}\\n\"}},\"status\":{\"state\":\"A\"}}\n","kubectl.kubernetes.io/last-applied-configuration":"{\"apiVersion\":\"project.dev/v1\",\"kind\":\"Test\",\"metadata\":{\"annotations\":{},\"name\":\"test\",\"namespace\":\"dev-kopf-state-event-loss\"},\"spec\":{\"key\":\"value\"},\"status\":{\"state\":\"A\"}}\n","project.dev/test":"1"},"creationTimestamp":"2025-07-27T16:27:11Z","generation":1,"managedFields":[{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{".":{},"f:kubectl.kubernetes.io/last-applied-configuration":{}}},"f:spec":{".":{},"f:key":{}}},"manager":"kubectl-client-side-apply","operation":"Update","time":"2025-07-27T16:27:11Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:status":{}},"manager":"kubectl-patch","operation":"Update","subresource":"status","time":"2025-07-27T16:27:20Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{"f:project.dev/test":{}}}},"manager":"kubectl-patch","operation":"Update","time":"2025-07-27T16:27:21Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:status":{"f:state":{}}},"manager":"OpenAPI-Generator","operation":"Update","subresource":"status","time":"2025-07-27T16:27:26Z"},{"apiVersion":"project.dev/v1","fieldsType":"FieldsV1","fieldsV1":{"f:metadata":{"f:annotations":{"f:kopf.zalando.org/last-handled-configuration":{}}}},"manager":"kopf","operation":"Update","time":"2025-07-27T16:27:26Z"}],"name":"test","namespace":"dev-kopf-state-event-loss","resourceVersion":"130813093","uid":"6eece680-c658-4567-9cbe-b053cbb66933"},"spec":{"key":"value"},"status":{"state":"C"}}

[2025-07-27 19:27:26,383] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:27:26,384] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:27:26,384] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Patching with: {'metadata': {'annotations': {'kopf.zalando.org/on_state_changed.status': '{"started":"2025-07-27T16:27:26.314962+00:00","stopped":"2025-07-27T16:27:26.384339+00:00","purpose":"update","retries":1,"success":true,"failure":false}', 'kopf.zalando.org/on_test_anno_scheduling.metadata.annotations': '{"started":"2025-07-27T16:27:26.314977+00:00","purpose":"update","retries":0,"success":false,"failure":false}'}}, 'status': {'kopf': {'progress': {'on_state_changed/status': {'started': '2025-07-27T16:27:26.314962+00:00', 'stopped': '2025-07-27T16:27:26.384339+00:00', 'delayed': None, 'purpose': 'update', 'retries': 1, 'success': True, 'failure': False, 'message': None, 'subrefs': None}, 'on_test_anno_scheduling/metadata.annotations': {'started': '2025-07-27T16:27:26.314977+00:00', 'stopped': None, 'delayed': None, 'purpose': 'update', 'retries': 0, 'success': False, 'failure': False, 'message': None, 'subrefs': None}}}}}
[2025-07-27 19:27:26,695] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating is in progress: {'apiVersion': 'project.dev/v1', 'kind': 'Test', 'metadata': {'annotations': {'kopf.zalando.org/last-handled-configuration': '{"spec":{"key":"value"},"metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\\"apiVersion\\":\\"project.dev/v1\\",\\"kind\\":\\"Test\\",\\"metadata\\":{\\"annotations\\":{},\\"name\\":\\"test\\",\\"namespace\\":\\"dev-kopf-state-event-loss\\"},\\"spec\\":{\\"key\\":\\"value\\"},\\"status\\":{\\"state\\":\\"A\\"}}\\n"}},"status":{"state":"A"}}\n', 'kopf.zalando.org/on_state_changed.status': '{"started":"2025-07-27T16:27:26.314962+00:00","stopped":"2025-07-27T16:27:26.384339+00:00","purpose":"update","retries":1,"success":true,"failure":false}', 'kopf.zalando.org/on_test_anno_scheduling.metadata.annotations': '{"started":"2025-07-27T16:27:26.314977+00:00","purpose":"update","retries":0,"success":false,"failure":false}', 'kubectl.kubernetes.io/last-applied-configuration': '{"apiVersion":"project.dev/v1","kind":"Test","metadata":{"annotations":{},"name":"test","namespace":"dev-kopf-state-event-loss"},"spec":{"key":"value"},"status":{"state":"A"}}\n', 'project.dev/test': '1'}, 'creationTimestamp': '2025-07-27T16:27:11Z', 'generation': 1, 'managedFields': [{'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'.': {}, 'f:kubectl.kubernetes.io/last-applied-configuration': {}}}, 'f:spec': {'.': {}, 'f:key': {}}}, 'manager': 'kubectl-client-side-apply', 'operation': 'Update', 'time': '2025-07-27T16:27:11Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {}}, 'manager': 'kubectl-patch', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:20Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'f:project.dev/test': {}}}}, 'manager': 'kubectl-patch', 'operation': 'Update', 'time': '2025-07-27T16:27:21Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {'f:state': {}}}, 'manager': 'OpenAPI-Generator', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:26Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:metadata': {'f:annotations': {'f:kopf.zalando.org/last-handled-configuration': {}, 'f:kopf.zalando.org/on_state_changed.status': {}, 'f:kopf.zalando.org/on_test_anno_scheduling.metadata.annotations': {}}}}, 'manager': 'kopf', 'operation': 'Update', 'time': '2025-07-27T16:27:26Z'}, {'apiVersion': 'project.dev/v1', 'fieldsType': 'FieldsV1', 'fieldsV1': {'f:status': {'f:kopf': {'.': {}, 'f:progress': {'.': {}, 'f:on_state_changed/status': {'.': {}, 'f:failure': {}, 'f:purpose': {}, 'f:retries': {}, 'f:started': {}, 'f:stopped': {}, 'f:success': {}}, 'f:on_test_anno_scheduling/metadata.annotations': {'.': {}, 'f:failure': {}, 'f:purpose': {}, 'f:retries': {}, 'f:started': {}, 'f:success': {}}}}}}, 'manager': 'kopf', 'operation': 'Update', 'subresource': 'status', 'time': '2025-07-27T16:27:26Z'}], 'name': 'test', 'namespace': 'dev-kopf-state-event-loss', 'resourceVersion': '130813095', 'uid': '6eece680-c658-4567-9cbe-b053cbb66933'}, 'spec': {'key': 'value'}, 'status': {'kopf': {'progress': {'on_state_changed/status': {'failure': False, 'purpose': 'update', 'retries': 1, 'started': '2025-07-27T16:27:26.314962+00:00', 'stopped': '2025-07-27T16:27:26.384339+00:00', 'success': True}, 'on_test_anno_scheduling/metadata.annotations': {'failure': False, 'purpose': 'update', 'retries': 0, 'started': '2025-07-27T16:27:26.314977+00:00', 'success': False}}}, 'state': 'C'}}
[2025-07-27 19:27:26,695] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating diff: (('change', ('status', 'state'), 'A', 'C'), ('add', ('metadata', 'annotations', 'project.dev/test'), None, '1'))
[2025-07-27 19:27:26,695] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Handler 'on_test_anno_scheduling/metadata.annotations' is invoked.
[2025-07-27 19:27:26,695] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] on_test_anno_scheduling handler is called
[2025-07-27 19:27:26,696] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_test_anno_scheduling/metadata.annotations' succeeded.
[2025-07-27 19:27:26,697] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Updating is processed: 2 succeeded; 0 failed.
[2025-07-27 19:27:26,697] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Patching with: {'metadata': {'annotations': {'kopf.zalando.org/on_test_anno_scheduling.metadata.annotations': None, 'kopf.zalando.org/on_state_changed.status': None, 'kopf.zalando.org/last-handled-configuration': '{"spec":{"key":"value"},"metadata":{"annotations":{"kubectl.kubernetes.io/last-applied-configuration":"{\\"apiVersion\\":\\"project.dev/v1\\",\\"kind\\":\\"Test\\",\\"metadata\\":{\\"annotations\\":{},\\"name\\":\\"test\\",\\"namespace\\":\\"dev-kopf-state-event-loss\\"},\\"spec\\":{\\"key\\":\\"value\\"},\\"status\\":{\\"state\\":\\"A\\"}}\\n","project.dev/test":"1"}},"status":{"state":"C"}}\n'}}, 'status': {'kopf': {'progress': {'on_test_anno_scheduling/metadata.annotations': None, 'on_state_changed/status': None}}}}

Additional information

Steps to reproduce

1. Create test CRD (attachments).
2. Create test namespace and test resource (attachments).
3. Run controller kopf run -v main.py -n dev-kopf-state-event-loss.
4. Run kubectl commands (one after another immediately):

kubectl patch test test -n dev-kopf-state-event-loss --subresource status -p '{"status": {"state": "A"}}' --type merge
kubectl patch test test -n dev-kopf-state-event-loss -p '{"metadata": {"annotations": {"project.dev/test": "1"}}}' --type merge

**

crd.yaml.txt
namespace.yaml.txt
test.yaml.txt

**

Problem description

Normal state processing sequence: A -> B -> C. When on_state_changed handler is processing state B, and sets state to 'C', there are already queued event of annotation update. This event triggers on_test_anno_scheduling handler, and its diff includes ('change', ('status', 'state'), 'A', 'C') (note: not 'B', 'C'). After on_test_anno_scheduling handler is completed, new execution of on_state_changed is not triggered. For some reasons kopf thinks that status.state change B to C is already handled by all handlers.

Workaround

To cope with it, we can just add another filter to on_test_anno_scheduling handler:

@kopf.on.update('project.dev',
                'tests',
                field=f'metadata.annotations',
                when=kopf.all_([is_test_anno_set,
                                state_is_not_changed]))
def on_test_anno_scheduling(spec, name, namespace, body, runtime, logger, **_):
    logger.info('on_test_anno_scheduling handler is called')

This gives us correct log:

[2025-07-27 19:43:09,638] kopf.activities.star [INFO    ] Sync load kubeconfig
[2025-07-27 19:43:09,647] kopf.activities.star [INFO    ] Client is configured via kubeconfig file.
[2025-07-27 19:43:09,647] kopf.activities.star [INFO    ] Activity 'setup-k8s-client' succeeded.
[2025-07-27 19:43:09,648] kopf._core.engines.a [INFO    ] Initial authentication has been initiated.
[2025-07-27 19:43:09,657] kopf.activities.auth [INFO    ] Activity 'login_via_client' succeeded.
[2025-07-27 19:43:09,657] kopf._core.engines.a [INFO    ] Initial authentication has finished.
[2025-07-27 19:43:20,294] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state A
[2025-07-27 19:43:25,300] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state B
[2025-07-27 19:43:25,404] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:43:25,405] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:43:25,405] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Creation is processed: 1 succeeded; 0 failed.
[2025-07-27 19:43:25,869] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state B
[2025-07-27 19:43:25,870] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Going to state C
[2025-07-27 19:43:25,968] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] dev-kopf-state-event-loss/test is patched
[2025-07-27 19:43:25,969] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:43:25,969] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Updating is processed: 1 succeeded; 0 failed.
[2025-07-27 19:43:26,108] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Processing state C
[2025-07-27 19:43:26,109] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Terminal state C
[2025-07-27 19:43:26,109] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Handler 'on_state_changed/status' succeeded.
[2025-07-27 19:43:26,109] kopf.objects         [INFO    ] [dev-kopf-state-event-loss/test] Updating is processed: 1 succeeded; 0 failed.

But this solution is not always possible, because this way on_test_anno_scheduling handler is not triggered at all.

Also batching disabling (setting batch size to 0) helps, but leads to execution of on_test_anno_scheduling handler 4 or 5 times in this example.

[nolar]

UPD: Turns out, this is an incorrect assumption. This is another issue. See the next comment instead.

Hello. Thanks for the detialed report. That will help a lot with reproducing & analysing it.

Could it be connected to and caused by an issue described (and presumably fixed) in this PR?

• Process events instantly and consistently, stop skipping the events due to "batching" #844

Long story short, there is a thing in Kopf called "batching" of arriving events within the 0.1-second time windows (sometimes continuous, so it can take longer than 0.1s). Only the latest event is considered the new state, and is processed. All intermediate states are ignored. That PR refactors the whole approach to replace the time-window-based "batching" with the proper reliance on the "resource versions" as provided by Kubernetes. That bug was difficult to catch, reproduce, and even comprehend — but your described symptoms at least look like those caused by immediate arrival of 2+ events and thus ignoring some of them but the last one.

I am a little bit —4 years, to be precise— late with that PR, which was functional and fixing the issue back then. But then I was discracted by a need to write proper tests, which in turn required some asyncio timing magic, which in turn gave birth to looptime and kmock — but then I was distracted by life events and had no time & energy to unfold this sequence back to its roots, and forgot what was needed for what :-)

The good thing is that Kopf has barely changed since then, too — for the same reasons. So, rebasing the branch and re-applying that new logic should be easy. Maybe there are some minor merge conflicts, but not in the logic or architecture itself.

The bad thing is that I myself currently still have no capacity for any open-source or coding activity, but I expect this to change soon'ish (within a couple months probably, if not weeks) — and that swarm of libraries and a sequence of PRs leading to the mentioned refactoring is the number one priority in the open-source field for me. But no promises on the specific timeline, sorry.

[nolar]

So, after a thorough review of the logs, I can state it has nothing to do with #844. That could only cause double-execution of the handlers, not skipping them. Here is the explanation of what happened and how to work around that.

---

What happens:

As I see from the logs, this is the tricky part where it misbehaves — and it is as intended in Kubernetes.

[2025-07-27 19:27:26,695] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating is in progress: ………
[2025-07-27 19:27:26,695] kopf.objects         [DEBUG   ] [dev-kopf-state-event-loss/test] Updating diff: (('change', ('status', 'state'), 'A', 'C'), ('add', ('metadata', 'annotations', 'project.dev/test'), None, '1'))

What happens here, is that there are 2 update handlers. Kopf executes every handler in its own separate cycle of patching & watching & reacting (unless configured with kopf.set_default_lifecycle(all_at_once) on the module level).

After the 1st handler, it applies the state=C via the API, but the overall update is not yet finished. When it comes to the 2nd handler, it still uses the last fully handled baseline as the reference, which was state=A when the update began. And now, it sees the diff A->C, and executes the 2nd handler with that diff.

When the 2nd handler ends, the fully handled state of the object is remembered in the …/last-handled-configuration, which includes state=C as seen at the last cycle.

As a result, the 1st handler is NOT called for the B->C transition as there is no more changes happening from Kopf's point of view.

---

Root cause:

There is no tracking of additional changes happening during the update cycles (too difficult to implement, since it will require tracking the diffbase content for every handler individually, not for the whole object in the …/last-handled-configuration annotation).

I tried solving this problem in the early days, failed hard (twice), reverted. Solving this behaviour is non-trivial.

• [PR] Ensure that all handlers get the latest state (eventually) #163
• [PR] Revert "Ensure that all handlers get the latest state (eventually)" #182

You should not expect this issue solved any time soon (maybe someday).

---

Workarounds:

I can recommend these ways to go around this problem:

• Set the kopf.set_default_lifecycle(all_at_once) on the module/import level if the operator's concept permits that behaviour (executing all applicable handlers at once instead of doing one handler per cycle). This behaviour is not documented, but is stable and a part of the public interface and will remain such. The default is kopf.set_default_lifecycle(kopf._core.actions.lifecycles.asap).
• Try packing it all into one handler in the same operator, so that it has everything done in one cycle (similar to the all_at_once solution).
• Redesign the operator to use daemons/timers to keep track of the states and transitions.

The mentioned lifecycle function should be this (from kopf._cogs.actions.lifecycles):

import kopf

def all_at_once(handlers: Handlers, **_: Any) -> Handlers:
    """ Execute all handlers at once, in one event reaction cycle, if possible. """
    return handlers

kopf.set_default_lifecycle(all_at_once)

@kopf.on.update(…)
def …(…):
    …

Other lifecycle strategies used (or not used) inside of Kopf — they are quite simple, actually:

• https://github.com/nolar/kopf/blob/1.42.4/kopf/_core/actions/lifecycles.py

[valen7in]

Thank you for an answer. Now behavior is clear.

I was wrong in my assumption, that for each resource only one handler can be executed at a time, no two handlers for each resource can be executed simultaneously. Trying to get a better grip on how kopf works I have read issues discussions. And in one of them I found this explanation:

On the one hand, while individual objects are parallelised (via the multiplexing logic), each individual object is always handled sequentially. It means the "worker" for that individual object is not doing anything because its task is somewhere in the handler currently, so it will not start a new handler until the previous one is finished.

And it sounds like unit of execution is "worker", not "handler".

Based on my experience of using kopf, I'd like to give some feedback if you don't mind.

1. Documentation lacks details of kopf internals, and how they affect applications built on top of kopf.
2. As it seemed to me, documentation encourage active use of handlers. Filters, different types of events, fields - all of them provide kind of "routing" for "business logic". After this issue, I think that fewer handlers (one handler) are better, and it is better to shift "routing" to application level. Because otherwise developer will likely have to solve complex consistency issues. Probably it is worth mentioning in docs in some way.

[nolar]

I was wrong in my assumption, that for each resource only one handler can be executed at a time, no two handlers for each resource can be executed simultaneously.

You were right in this assumption. For one resource (object), only one handler runs at a time — no parallelism or concurrency. But maybe 2+ handlers in one processing cycle (the default is one handler per cycle). The "cycle" is everything after an eligible watch-event arrives from the API and until the accumulated patch goes out to the API.

Based on my experience of using kopf, I'd like to give some feedback if you don't mind.

The feedback is always welcome! This helps me improve the library.

1. Documentation lacks details of kopf internals, and how they affect applications built on top of kopf.

Noted. I am now planing and working on improvements of things here & there — since I have some time. The improvement of docs for LLM consumption is definitely planned — I mean, for LLMs writing operators using Kopf, not writing Kopf itself. But maybe this also — I am now accumulating and growing the agentic guidlines and skills in the repo (not committed) to make it easier for agents to code Kopf itself. Also the website for ease of finding Kopf (done).

But not everything at once. One thing at a time.

2. After this issue, I think that fewer handlers (one handler) are better, and it is better to shift "routing" to application level. Because otherwise developer will likely have to solve complex consistency issues. Probably it is worth mentioning in docs in some way.

Agree. You are right pointing out to this confusion. Kopf indeed promotes using the handlers as units of work, but the intention was using handlers and decorators with different resources and maybe filters. This issue is a blocker to smooth usage of that approach.

I am now trying to solve some consistency issues already (one big thing solved, another is in progress). But this one can be conceptually unsolveable. I need to think on it first — maybe I can revive tha old PR that I mentioned and try it again. Or give up on multi-handler docs and add the warnings on multi-handler logic.

Thanks for the feedback, @valen7in !