kopf
kopf copied to clipboard
nolar
Update event lost and handler is not fired
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
- Create test CRD (attachments).
- Create test namespace and test resource (attachments).
- Run controller
kopf run -v main.py -n dev-kopf-state-event-loss. - 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.
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?
- #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.
