Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

kubelet: fix pod log line corruption when using timestamps and long lines #113481

Merged
merged 1 commit into from Nov 2, 2022
Merged

kubelet: fix pod log line corruption when using timestamps and long lines #113481

merged 1 commit into from Nov 2, 2022

Conversation

rphillips
Copy link
Member

@rphillips rphillips commented Oct 31, 2022 •
edited

What type of PR is this?

/kind bug

What this PR does / why we need it:

This PR resurrects #77822 which didn't merge and improves upon it.

When using "--timestamps" from the API to get a pod's logs the Kubelet will use a default Golang Bufferr (4096 bytes) to transfer the log to the API stream. This causes timestamps to be intermingled in the output because the code arbitrarily injects the timestamp after every buffer iteration. [source]

The fix is to check the line ending of the buffer to see if the timestamp should be appended.

  • Test Case

Which issue(s) this PR fixes:

Fixes #77603

Special notes for your reviewer:

logs.yml:

apiVersion: v1
kind: Pod
metadata:
  name: logs
spec:
  restartPolicy: Never
  containers:
  - name: logs
    image: fedora
    args:
    - bash
    - -c
    - 'for i in `seq 1 4096`; do echo -n $i; done'

Fetch the logs:

kubectl logs logs --timestamps

Does this PR introduce a user-facing change?

Pod logs using --timestamps are not broken up with timestamps anymore.

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

NONE

@k8s-ci-robot k8s-ci-robot added release-note Denotes a PR that will be considered when it comes time to generate release notes. kind/bug Categorizes issue or PR as related to a bug. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Oct 31, 2022
@k8s-ci-robot
Copy link
Contributor

@rphillips: This issue is currently awaiting triage.

If a SIG or subproject determines this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.

The triage/accepted label can be added by org members by writing /triage accepted in a comment.

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.

@k8s-ci-robot k8s-ci-robot added the needs-priority Indicates a PR lacks a `priority/foo` label and requires one. label Oct 31, 2022
@k8s-ci-robot k8s-ci-robot added area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Oct 31, 2022
@openshift-ci-robot openshift-ci-robot mentioned this pull request Oct 31, 2022
Merged
@harche
Copy link
Contributor

harche commented Nov 1, 2022

Verified it locally that the fix indeed fixes the issue.

/lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Nov 1, 2022
@shanemcd
Copy link

shanemcd commented Nov 1, 2022

Works for me too!

Before:

198326988-8347267b-14cd-4921-952e-3b3debcd7a60

After:

image

🎉

@shanemcd shanemcd mentioned this pull request Nov 1, 2022
Merged
@derekwaynecarr
Copy link
Member

/assign

thanks for the clear test case and images.

/approve
/lgtm

@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: derekwaynecarr, rphillips

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Nov 1, 2022
@rphillips rphillips mentioned this pull request Nov 1, 2022
Merged
@rphillips
Copy link
Member Author

/priority important-soon

@k8s-ci-robot k8s-ci-robot added priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. and removed needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Nov 1, 2022
@k8s-ci-robot k8s-ci-robot merged commit 5899432 into kubernetes:master Nov 2, 2022
@k8s-ci-robot k8s-ci-robot added this to the v1.26 milestone Nov 2, 2022
@thees
Copy link

thees commented Nov 2, 2022 •
edited

will this fix be cherry-picked into older k8s versions? if so, which versions?
(we are waiting for this, because we experience the mentioned AWX problem on GKE running 1.23)

EDIT: ah saw the PRs up to 1.23 from @rphillips . Thanks 👍🏻

k8s-ci-robot added a commit that referenced this pull request Nov 2, 2022
@k8s-ci-robot
Merge pull request #113515 from rphillips/automated-cherry-pick-of-#1…
eb92f1b 
…13481-upstream-release-1.25

Automated cherry pick of #113481: kubelet: fix pod log line corruption when using timestamps
This was referenced Nov 2, 2022
Merged
Merged
Closed
@openshift-ci-robot openshift-ci-robot mentioned this pull request Nov 16, 2022
Merged
@TheRealHaoLiu TheRealHaoLiu mentioned this pull request Nov 16, 2022
Closed
TheRealHaoLiu added a commit to TheRealHaoLiu/receptor that referenced this pull request Nov 28, 2022
@TheRealHaoLiu @shanemcd @fosterseth
add retry logic to receptor logstream on kube
36facda 
resume kube job log using kube log timestamp

require fix for kubernetes/kubernetes#77603
in kubernetes/kubernetes#113481

fix is backported to the following kubernetes version
- 1.23.14
- 1.24.8
- 1.25.4

required fix for ansible/ansible-runner#1161

fix is backported to the following ansible-runner version
- 2.2.2
- 2.3.1

added `RECEPTOR_KUBE_SUPPORT_RECONNECT`  with following options:

- “enabled”: this option will use timestamp with the log and enable our new code path
- “disabled”: this option will not use timestamp and use the original code path
- “auto”: auto detect if it's appropriate to enable timestamp base on kube version

Co-Authored-By: Shane McDonald <me@shanemcd.com>
Co-Authored-By: Seth Foster <fosterseth@users.noreply.github.com>
TheRealHaoLiu added a commit to TheRealHaoLiu/receptor that referenced this pull request Nov 28, 2022
@TheRealHaoLiu @shanemcd @fosterseth
add retry logic to receptor logstream on kube
b128f51 
resume kube job log using kube log timestamp

require fix for kubernetes/kubernetes#77603
in kubernetes/kubernetes#113481

fix is backported to the following kubernetes version
- 1.23.14
- 1.24.8
- 1.25.4

required fix for ansible/ansible-runner#1161

fix is backported to the following ansible-runner version
- 2.2.2
- 2.3.1

added `RECEPTOR_KUBE_SUPPORT_RECONNECT`  with following options:

- “enabled”: this option will use timestamp with the log and enable our new code path
- “disabled”: this option will not use timestamp and use the original code path
- “auto”: auto detect if it's appropriate to enable timestamp base on kube version

Co-Authored-By: Shane McDonald <me@shanemcd.com>
Co-Authored-By: Seth Foster <fosterseth@users.noreply.github.com>
Signed-off-by: Hao Liu <haoli@redhat.com>
shanemcd added a commit to ansible/receptor that referenced this pull request Dec 8, 2022
@TheRealHaoLiu @shanemcd @fosterseth
add retry logic to receptor logstream on kube
3c94e6c 
resume kube job log using kube log timestamp

require fix for kubernetes/kubernetes#77603
in kubernetes/kubernetes#113481

fix is backported to the following kubernetes version
- 1.23.14
- 1.24.8
- 1.25.4

required fix for ansible/ansible-runner#1161

fix is backported to the following ansible-runner version
- 2.2.2
- 2.3.1

added `RECEPTOR_KUBE_SUPPORT_RECONNECT`  with following options:

- “enabled”: this option will use timestamp with the log and enable our new code path
- “disabled”: this option will not use timestamp and use the original code path
- “auto”: auto detect if it's appropriate to enable timestamp base on kube version

Co-Authored-By: Shane McDonald <me@shanemcd.com>
Co-Authored-By: Seth Foster <fosterseth@users.noreply.github.com>
Signed-off-by: Hao Liu <haoli@redhat.com>
hansenms pushed a commit to microsoft/tyger that referenced this pull request Aug 14, 2023
@johnstairs
Merged PR 71750: Upgrade AKS k8s, kubectl, and Helm versions
a46288c 
The Kubernetes version we were using is no longer supported by AKS.

Update: Also needed to remove a workaround we had put in for handling long log lines. This was fixed in k8s [here](kubernetes/kubernetes#113481).
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@derekwaynecarr derekwaynecarr Awaiting requested review from derekwaynecarr

@krmayankk krmayankk Awaiting requested review from krmayankk

Assignees

@derekwaynecarr derekwaynecarr

@harche harche

Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. area/kubelet cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/bug Categorizes issue or PR as related to a bug. lgtm "Looks good to me", indicates that a PR is ready to be merged. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. release-note Denotes a PR that will be considered when it comes time to generate release notes. sig/node Categorizes an issue or PR as relevant to SIG Node. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Milestone
v1.26
Development

Successfully merging this pull request may close these issues.

Pod logs: long lines are corrupted when using timestamps=true
6 participants
@rphillips @k8s-ci-robot @harche @shanemcd @derekwaynecarr @thees