JSON-patch values update partially broken

[yalosev]

Hello.
I have met weird behavior of json patch in addon-operator.

Short description:

• array add works but sometimes rewrite full array instead of appending (rarely, I can't reproduce it in 100% times) - its not a main goal
• json patch array remove doesn't work at all. The temporary json-patch is created, applied by operator (guess so, because the file has been disappeared), hook is finished successfully but no values have been changed.

You can find detailed description and live demo here

This code expected to work based on the examples and articles but it doesn't. Maybe I'm doing something wrong, then point me to the error, please.

Thank you.

[diafour]

Hello! Thank you for the demo, it is easy to reproduce bugs with such a description!

It seems the problem is > bash redirection instead of >> here and here. Can you try to reproduce with >> in your environment?

[yalosev]

Thank you for paying attention @diafour.
Looks like the situation hasn't changed or even worsened since the bash redirection in 'append' mode.

After initialization:

$ kubectl get cm pod-monitor-config -o jsonpath='{.data}'
# Output: {"pods.json":"[]\n"}
# hmmm, where is my default stub records?

Test deployment installed:

$ kubectl wait --for=condition=ready -n default -l app=test pod --timeout=120s
# Output: pod/test-848844fd9-wz4x6 condition met
$ kubectl get cm pod-monitor-config -o jsonpath='{.data}'
# Output: {"pods.json":"[\"test-848844fd9-wz4x6\"]\n"}

After scaling:

$ kubectl scale deployment test --replicas=2
$ kubectl get pods
# NAME                   READY   STATUS    RESTARTS   AGE
# test-848844fd9-wz4x6   1/1     Running   0          65s
# test-848844fd9-5v82z   1/1     Running   0          14s

$  microk8s kubectl get cm pod-monitor-config -o jsonpath='{.data}'
# Output: {"pods.json":"[\"test-848844fd9-5v82z\"]\n"}  - first value was erased

# logs from operator
time="2020-11-26T18:53:30Z" level=info msg="Module hook success '010-pod-monitor/hooks/entry.sh'" binding=kubernetes binding.name=OnCreateDeletePod event.id=81097b74-2ca4-4f66-a443-c7226d1ed35a hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor operator.component=taskRunner queue=main task.id=5a9650c8-bfad-4d45-ba7f-17613fc94cda watchEvent=Added
time="2020-11-26T18:53:30Z" level=info msg="Queue 'main' contains 0 converge tasks after handle 'ModuleHookRun'" binding=kubernetes binding.name=OnCreateDeletePod event.id=81097b74-2ca4-4f66-a443-c7226d1ed35a hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=5a9650c8-bfad-4d45-ba7f-17613fc94cda watchEvent=Added
time="2020-11-26T18:53:30Z" level=info msg="module values are changed, queue ModuleRun task" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=handleManagerEvents
time="2020-11-26T18:53:30Z" level=info msg="queue task ModuleRun:main:pod-monitor:ModuleValuesChanged" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=handleManagerEvents task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:33Z" level=info msg="ModuleRun 'Helm' phase" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=taskRunner task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:33Z" level=info msg="Render helm templates for chart '/modules/010-pod-monitor' was successful" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=helm queue=main task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:33Z" level=info msg="Running helm upgrade for release 'pod-monitor' with chart '/modules/010-pod-monitor' in namespace 'addon-operator' ..." event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=helm queue=main task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:35Z" level=info msg="Helm upgrade for release 'pod-monitor' with chart '/modules/010-pod-monitor' in namespace 'addon-operator' successful:\nRelease \"pod-monitor\" has been upgraded. Happy Helming!\nNAME: pod-monitor\nLAST DEPLOYED: Thu Nov 26 18:53:34 2020\nNAMESPACE: addon-operator\nSTATUS: deployed\nREVISION: 7\nTEST SUITE: None\n" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor operator.component=helm queue=main task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:35Z" level=info msg="ModuleRun success, module is ready" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor module.state=ready operator.component=taskRunner task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8
time="2020-11-26T18:53:35Z" level=info msg="Queue 'main' contains 0 converge tasks after handle 'ModuleRun'" event.id=2384aa4a-b7a6-42f7-924a-b7893c3c68cd event.type=ModulesChanged module=pod-monitor task.id=dc09794c-cf21-4ad9-a251-1873f65f07f8

Ok, never mind. Will try to scale to 1 and then to 0

$ kubectl scale deployment test --replicas=1
# deployment.apps/test scaled
$ kubectl get pods
# NAME                   READY   STATUS    RESTARTS   AGE
# test-848844fd9-wz4x6   1/1     Running   0          2m47s
$ kubectl get cm pod-monitor-config -o jsonpath='{.data}'
{"pods.json":"[\"test-848844fd9-5v82z\"]\n"}

$ kubectl scale deployment test --replicas=0
$ kubectl get pods
# No resources found in default namespace.

$ kubectl get cm pod-monitor-config -o jsonpath='{.data}'
# Output: {"pods.json":"[\"test-848844fd9-5v82z\"]\n"}


# logs from operator:
time="2020-11-26T18:55:26Z" level=info msg="Module hook success" binding=kubernetes binding.name=OnCreateDeletePod event.id=086a9108-f49d-415b-a2de-0afd4222d2f2 hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=ca339cea-ce0c-4e53-b5a1-701e513c6856 watchEvent=Deleted
time="2020-11-26T18:55:26Z" level=info msg="Module hook success '010-pod-monitor/hooks/entry.sh'" binding=kubernetes binding.name=OnCreateDeletePod event.id=086a9108-f49d-415b-a2de-0afd4222d2f2 hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor operator.component=taskRunner queue=main task.id=ca339cea-ce0c-4e53-b5a1-701e513c6856 watchEvent=Deleted
time="2020-11-26T18:55:26Z" level=info msg="Queue 'main' contains 0 converge tasks after handle 'ModuleHookRun'" binding=kubernetes binding.name=OnCreateDeletePod event.id=086a9108-f49d-415b-a2de-0afd4222d2f2 hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=ca339cea-ce0c-4e53-b5a1-701e513c6856 watchEvent=Deleted
time="2020-11-26T18:56:24Z" level=info msg="queue task ModuleHookRun:main:kubernetes:010-pod-monitor/hooks/entry.sh:OnCreateDeletePod:Kubernetes" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor operator.component=handleEvents queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Module hook start '010-pod-monitor/hooks/entry.sh'" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor operator.component=taskRunner queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Module hook start" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Pod test-848844fd9-wz4x6: -1 has been deleted" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor output=stdout queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Module hook success" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Module hook success '010-pod-monitor/hooks/entry.sh'" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor operator.component=taskRunner queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted
time="2020-11-26T18:56:26Z" level=info msg="Queue 'main' contains 0 converge tasks after handle 'ModuleHookRun'" binding=kubernetes binding.name=OnCreateDeletePod event.id=2f8d9d41-0b50-495e-a47d-863ff724768e hook=010-pod-monitor/hooks/entry.sh hook.type=module module=pod-monitor queue=main task.id=8e40c187-8f33-45b5-ac93-3796632806eb watchEvent=Deleted

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"19+", GitVersion:"v1.19.3-34+a56971609ff35a", GitCommit:"a56971609ff35ac8cc90b2aef89165208bff3fe1", GitTreeState:"clean", BuildDate:"2020-11-06T11:56:24Z", GoVersion:"go1.15.3", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"19+", GitVersion:"v1.19.3-34+a56971609ff35a", GitCommit:"a56971609ff35ac8cc90b2aef89165208bff3fe1", GitTreeState:"clean", BuildDate:"2020-11-06T11:57:19Z", GoVersion:"go1.15.3", Compiler:"gc", Platform:"linux/amd64"}

First time I met this behavior on local cluster but it's 100% reproducible on microk8s
Thought that it could be some kind of bug in microk8s, that's why I have tried one more time on Yandex managed k8s - got absolutely the same result.

Yandex version:

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"18", GitVersion:"v1.18.6", GitCommit:"dff82dc0de47299ab66c83c626e08b245ab19037", GitTreeState:"clean", BuildDate:"2020-07-15T16:58:53Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"16", GitVersion:"v1.16.13", GitCommit:"39a145ca3413079bcb9c80846488786fed5fe1cb", GitTreeState:"clean", BuildDate:"2020-07-15T16:10:14Z", GoVersion:"go1.13.9", Compiler:"gc", Platform:"linux/amd64"}

[diafour]

You can try another thing. It seems that indices tracking is cumbersome especially with bash. You can use a "snapshot" mode to receive all Pods at once and update /podMonitor/pods value. No need to have 2 handlers for "Synchronization" and "Event" binding context.

The config will be like this:

configVersion: v1
kubernetes:
  - name: OnCreateDeletePod
    apiVersion: v1
    kind: Pod
    namespace:
      nameSelector:
        matchNames: ["default"]
    executeHookOnEvent:
      - Added
      - Deleted
    jqFilter: ".metadata"
    keepFullObjectsInMemory: false
    includeSnapshotsFrom: 
    - OnCreateDeletePod

And the handler becomes much simpler:

ARRAY_COUNT=$(jq -r '. | length-1' $BINDING_CONTEXT_PATH)
for IND in `seq 0 $ARRAY_COUNT`; do
  objects=$(jq -r ".[0].snapshots.OnCreateDeletePod" $BINDING_CONTEXT_PATH)
  PODNAMES=$(echo $objects | jq -r "[.[].filterResult.name]")

  # 1. remove "/podMonitor/pods" if exists
  # 2. set new value for /podMonitor/pods

done

[diafour]

More details of indices tracking approach and JSON patches.

The addon-operator has two types of patches: patches of config values in $CONFIG_VALUES_JSON_PATCH_PATH that applies to cm/addon-operator immediately after hook run and patches of values in $VALUES_JSON_PATCH_PATH. Values patches are stored in memory. To construct effective values for hook, addon-operator merges values from values.yaml, config-values.yaml, cm/addon-operator and then applies patches from memory.

Let's look at what happens with your hook:

1. First, a new pod appears, and the hook returns:

{"op":"add", "path":"/podMonitor/pods/-", "value":"test-848844fd9-wz4x6"}

addon-operator saves this patch.

2. Next, a second pod appears:

Hook receives these values:

{"podMonitor":{"pods":["test-848844fd9-wz4x6"] }}

Hook returns this patch to add a new element:

{"op":"add", "path":"/podMonitor/pods/-", "value":"test-848844fd9-5v82z"}

addon-operator saves this patch and then applies a compaction algorithm, which treats "-" as a regular key and removes the first patch as a patch with the same key. The result of patches in memory:

{"op":"add", "path":"/podMonitor/pods/-", "value":"test-848844fd9-5v82z"}

Effective values for the next execution of the hook will be:

{"podMonitor":{"pods":["pod_name_2"] }}

Now, let's imagine that the addon-operator supports "-" keys. Patches in memory will have a stack of patches for "-" and an array of "add" operations with numerical indices. There is one thing that breaks this: multiple "remove" operations. A hook can receive a combined binding context with 2 "Delete" events and returns this patch:

[{"op":"remove", "path":"/podMonitor/pods/1"}]
[{"op":"remove, "path":"/podMonitor/pods/2"}]

What's the problem? A set of JSON patch applies one by one. The first operation removes element 1 and shifts other elements to the left: element 2 becomes element 1, element 3 becomes element 2, and so on. That is why the next operation removes element 3.

I think that is enough to consider that patches for array indices are not a good idea. If you want to store and patch an array in values, it is better to use "snapshot" mode and patch the array's full value, not individual indices.

[yalosev]

Thank you for such a detailed explanation. Sure, removing by index is not a good idea in very dynamic environments. It becomes classic "removing from array while iterating" and it's cumbersome in a situation like this (working with pods). In my situation it had been working in low-dynamic environment with nodes - they don't have such an active Create/Delete lifecycle. This example is based on a real module, which was written on 1.06.2019 for addon-operator:latest. That time addon-operator didn't have a "snapshot" engine. When I upgraded addon-operator to the last version and ported all modules, I got this broken example.

Sure I will rewrite on "snapshots" but I guess it's a good idea to pin your explanation/exception into the README. Because here you have the link to JSON-PATCH and json-patch has an array examples on the first page (The - character can be used instead of an index to insert at the end of an array), that's why it was expected to work and I decided to create an issue.

I think we are done here. Thank you for spending your time and for the solution. Feel free to close this issue if I can't be useful for something else - sharing some more details, for example.

Best wishes