Need better debug logging for patch operations

[MikeSpreitzer]

What would you like to be added:
I would like debug logging to show the heart of the processing of a patch request. For example, showing the inputs and outputs of https://github.com/kubernetes/apiserver/blob/fa3c8ad6d7aff4ba13bf7296583ed2815db1be44/pkg/endpoints/handlers/patch.go#L620 .

Why is this needed:
It is way too easy to botch a PATCH request. Due to the way JSON decoding happily and silently discards unexpected contents, it is very easy to accidentally write buggy code that provokes no error. There is no existing debug logging to help a developer see the error in their ways.
I spent a lot of time chasing a bug that was immediately evident when I put in debug logging about the line mentioned above.

[MikeSpreitzer]

@kubernetes/sig-api-machinery-feature-requests

[MikeSpreitzer]

/good-first-issue

[k8s-ci-robot]

@MikeSpreitzer:
This request has been marked as suitable for new contributors.

Please ensure the request meets the requirements listed here.

If this request no longer meets these requirements, the label can be removed
by commenting with the /remove-good-first-issue command.

In response to this:

/good-first-issue

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[MikeSpreitzer]

This may be particularly helpful to someone struggling with #89875

[tanjunchen]

/assign

[MikeSpreitzer]

FYI, for a comparison of similar debug logging you can try setting -v=5 and seeing what gets logged. You can also try some higher settings. You will see request bodies logged at the site where the call goes out. I did not see request bodies logged on the receiving side.

[MikeSpreitzer]

FYI, here is the debug logging statement that I used:

	klog.V(8).Infof("Applied %#+v to %#+v to produce %#+v, err=%#+v", patchMap, originalMap, patchedObjMap, err)

That was right after the call to strategicpatch.StrategicMergeMapPatch.

[MikeSpreitzer]

It would be appropriate to do the same for the case of JSON Patch and JSON Merge Patch as well as the stategic merge patch.

[liggitt]

I did not see request bodies logged on the receiving side.

That's somewhat intentional. Logging of API server request bodies without regard to whether the resource is a confidential one (e.g. secrets) would expose confidential content. If we add debug output of Request bodies to the API server log, we'll need to do so in a way that is not considered a vulnerability.

[MikeSpreitzer]

Good point. So would it suffice to carve out an exception for objects of the core Secret kind?

[liggitt]

So would it suffice to carve out an exception for objects of the core Secret kind?

The audit logging and storage encryption mechanisms do not special-case secret resources, I would not expect this to.

[fedebongio]

/assign @jennybuckley

[sresthas]

Can I take this up as my first issue? Any pointers would be helpful.

[MikeSpreitzer]

@twisted-sres : yes.
@liggitt : your last remark looks like a complete rejection of this issue. Is there something you think can be done here? Remember, the motivating problem is patch requests that DO NOT provoke errors yet fail to accomplish what the client developer expected. In extreme cases (the ones that actually provoked this issue), the non-erring patch request produced no change at all and I thought I had botched something server-side.

[liggitt]

your last remark looks like a complete rejection of this issue. Is there something you think can be done here?

In general, I don't want to increase the number of ways confidential data can leak into server logs. Are there other ways we could ease testing patches (like simpler use of patching functions in a library/unit test) or surface potential problems (like returning warnings, similar to the mechanism proposed in #73032)?

[MikeSpreitzer]

The particularly difficult thing about patching is that it is very easy for a client developer to make a mistake that produces an unexpected result and NO error NOR warning message on the server. Just goof up a field name or a bit of structure, and the patch has little or no effect on the target object.

I suppose it should be possible --- for JSON merge and for strategic merge patches --- to add a check on the server side, comparing the patch with the patched object to see if the patch contains material that does not appear in the patched object. It should be possible to also do a similar check for a JSON patch, looking for patch material that had no effect. Would there be a way to plumb a warning from these out to a reply header?

[liggitt]

Would there be a way to plumb a warning from these out to a reply header?

I actually just started a proposal for server -> client warnings (https://github.com/kubernetes/enhancements/tree/master/keps/sig-api-machinery/1693-warnings) which could surface something like that in the future, though getting the "field X in patch didn't exist so was ignored" plumbed out of the patch/json stack without erroring would be non-trivial as well.

[lavalamp]

Note that users can and should use dry run to verify their change will have the desired effect.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten

[leilajal]

@MikeSpreitzer what is the status of this issue? can we close this one if we follow up with the client warnings instead of generating new logs?

[fejta-bot]

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close

[k8s-ci-robot]

@fejta-bot: Closing this issue.

In response to this:

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/close

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.