Fix log timestamps to maintain a fixed width

[stevechuck]

What type of PR is this?
/kind cleanup

What this PR does / why we need it:

Fixed: log timestamps now include trailing zeros to maintain a fixed width

Which issue(s) this PR fixes:
Fixes #91186
Fixes #72292

Special notes for your reviewer:

Does this PR introduce a user-facing change?:

NONE

[k8s-ci-robot]

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.

---

• If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
• If you signed the CLA as a corporation, please sign in with your organization's credentials at https://identity.linuxfoundation.org/projects/cncf to be authorized.
• If you have done the above and are still having issues with the CLA being reported as unsigned, please log a ticket with the Linux Foundation Helpdesk: https://support.linuxfoundation.org/
• Should you encounter any issues with the Linux Foundation Helpdesk, send a message to the backup e-mail support address at: login-issues@jira.linuxfoundation.org

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. I understand the commands that are listed here.

[k8s-ci-robot]

Welcome @iamchuckss!

It looks like this is your first PR to kubernetes/kubernetes 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/kubernetes has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

[k8s-ci-robot]

Hi @iamchuckss. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

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.

[stevechuck]

/assign @derekwaynecarr

[Nuru]

@iamchuckss Thank you for pushing this forward. Here is a bit extra for you to include if you choose:

• Add: Fixes Container logs with timestamp are getting trailing zeroes trimmed #72292 (it was closed as rotten, not fixed or dismissed)
• Add release notes:

Fixed: log timestamps now include trailing zeros to maintain a fixed width

[dashpole]

We should probably update the KEP that says we will use the previous timestamp format. Since the CRI logging format is an API, I consider this to be an API change, although I can't tell if there will be any backwards-compatibility issues here. It would be helpful to describe what changes would be required for container runtimes (if any), and what changes would be required for log consumers (if any).

/ok-to-test
/kind api-change

[fejta-bot]

This PR may require API review.

If so, when the changes are ready, complete the pre-review checklist and request an API review.

Status of requested reviews is tracked in the API Review project.

[Nuru]

@dashpole Not exactly sure what you mean by "the KEP that says we will use the previous timestamp format". Do you mean this? That proposal has not been adopted, as you can tell by the fact that logs do not include the Full or Partial indicator being proposed under "Log format", which is also where the timestamp format is proposed. That proposal is for the logging coming out of the Container Runtime, which this PR does not affect.

I do not know where else the format is discussed. "RFC3339Nano" is mentioned is some of the documentation, but to be fair, it is not a real standard and Docker claims to output its logs in RFC3339Nano but is actually using the proposed RFC3339NanoFixed.

It would be helpful to describe what changes would be required for container runtimes (if any), and what changes would be required for log consumers (if any).

It would be a very odd piece of software that would be negatively affected by this change. The change consists of keeping rather than trimming/removing trailing zeros in log timestamps. What is currently this:

2020-05-11T00:59:53.112926311Z INFO log output 1
2020-05-11T00:59:53.11319083Z INFO log output 2
2020-05-11T00:59:53.262609142Z WARN log output x

will become this:

2020-05-11T00:59:53.112926311Z INFO log output 1
2020-05-11T00:59:53.113190830Z INFO log output 2
2020-05-11T00:59:53.262609142Z WARN log output x

To the extent any consumer is using timestamps, this increased consistency is likely to be solving problems and fixing hidden bugs rather than creating them. It is a bit hard for me to imagine a system relying on this current behavior. It is possible that a system that tries to compensate for this behavior might be tricked into overcompensating, but that strikes me as unlikely.

@iamchuckss I do not understand the build failures, but am happy to help if my help is needed/wanted. These appear to be build failures, and since I do not understand the build system and have never been able to get it to work locally, I really do not understand what is going wrong.

My best guess it that the builder is trying to build pkg/kubelet/kuberuntime/logs but does not have the updated k8s.io/kubernetes/pkg/kubelet/types. Maybe this will help:

Add "//pkg/kubelet/types:go_default_library" to BUILD deps

diff --git a/pkg/kubelet/kuberuntime/logs/BUILD b/pkg/kubelet/kuberuntime/logs/BUILD
index 18b4c8ec45a..42cde17e300 100644
--- a/pkg/kubelet/kuberuntime/logs/BUILD
+++ b/pkg/kubelet/kuberuntime/logs/BUILD
@@ -6,6 +6,7 @@ go_library(
     importpath = "k8s.io/kubernetes/pkg/kubelet/kuberuntime/logs",
     visibility = ["//visibility:public"],
     deps = [
+        "//pkg/kubelet/types:go_default_library",
         "//pkg/util/tail:go_default_library",
         "//staging/src/k8s.io/api/core/v1:go_default_library",
         "//staging/src/k8s.io/cri-api/pkg/apis:go_default_library",

[dashpole]

That proposal has not been adopted, as you can tell by the fact that logs do not include the Full or Partial indicator being proposed under "Log format", which is also where the timestamp format is proposed.

I believe the proposal was implemented? #55922.

To the extent any consumer is using timestamps, this increased consistency is likely to be solving problems and fixing hidden bugs rather than creating them. It is a bit hard for me to imagine a system relying on this current behavior. It is possible that a system that tries to compensate for this behavior might be tricked into overcompensating, but that strikes me as unlikely.

Great. That is what I was looking for. The example was helpful.

[Nuru]

That proposal has not been adopted, as you can tell by the fact that logs do not include the Full or Partial indicator being proposed under "Log format", which is also where the timestamp format is proposed.

I believe the proposal was implemented? #55922.

@dashpole Sorry, I was a bit confused. The document I referred to is a proposal...

...to define how container's stdout/stderr log streams should be handled in CRI. The explicit non-goal is to define how (non-stdout/stderr) application logs should be handled.

While that proposal was partly implemented in #55922, it defines the log format output by the Container Runtime and parsed by kubelet (and fluentd and others). Our PR here does not modify that interface in any way. We have specifically created a separate timeFormatIn which is identical to the currently used RFC3339Nano to be used in all input and parsing operations, so while the name of the variable has changed, the value has not. Also, as I have stated previously, Docker, the most commonly use Container Runtime, already outputs logs with fixed-width timestamps.

Our PR only affects the Pod's Read Log API, and although it is documented to optionally add "an RFC3339 or RFC3339Nano timestamp at the beginning of every line of log output", the fact that RFC3339 and RFC3339Nano reference Go language formats is not made clear, so I think this change is not violating the spirit of the documentation.

There is no option for choosing between RFC3339 or RFC3339Nano formats so it is already unclear what to expect. RFC 3339 (the standard, not the constant) allows any number of digits for the fractional second representation. Still, I think it is worth updating the documentation.

@iamchuckss 3 more minor changes for you:

Revise documentation of Read Log API

diff --git a/pkg/apis/core/types.go b/pkg/apis/core/types.go
index 3944d5dcadc..9418a118eac 100644
--- a/pkg/apis/core/types.go
+++ b/pkg/apis/core/types.go
@@ -4252,7 +4252,7 @@ type PodLogOptions struct {
        // If this value is in the future, no logs will be returned.
        // Only one of sinceSeconds or sinceTime may be specified.
        SinceTime *metav1.Time
-       // If true, add an RFC3339 or RFC3339Nano timestamp at the beginning of every line
+       // If true, add an RFC 3339 timestamp with 9 digits of fractional seconds at the beginning of every line
        // of log output.
        Timestamps bool
        // If set, the number of lines from the end of the logs to show. If not specified,

Revise documentation of format variables API

diff --git a/pkg/kubelet/kuberuntime/logs/logs.go b/pkg/kubelet/kuberuntime/logs/logs.go
index 07f8782d594..e06709e3696 100644
--- a/pkg/kubelet/kuberuntime/logs/logs.go
+++ b/pkg/kubelet/kuberuntime/logs/logs.go
@@ -48,8 +48,9 @@ import (
 // TODO(random-liu): Support log rotation.
 
 const (
-       // timeFormatOut and timeFormatIn are time formats used in the log.
+       // timeFormatOut is the format for writing timestamps to output.
        timeFormatOut = types.RFC3339NanoFixed
+       // timeFormatIn is the format for parsing timestamps from other logs.
        timeFormatIn  = types.RFC3339NanoLenient
 
        // logForceCheckPeriod is the period to check for a new read

Modify test to detect timestamp truncation

diff --git a/pkg/kubelet/kuberuntime/logs/logs_test.go b/pkg/kubelet/kuberuntime/logs/logs_test.go
index 25e3bd20e59..f53b93037e6 100644
--- a/pkg/kubelet/kuberuntime/logs/logs_test.go
+++ b/pkg/kubelet/kuberuntime/logs/logs_test.go
@@ -143,7 +143,7 @@ func TestParseLog(t *testing.T) {
 }
 
 func TestWriteLogs(t *testing.T) {
-       timestamp := time.Unix(1234, 4321)
+       timestamp := time.Unix(1234, 43210)
        log := "abcdefg\n"
 
        for c, test := range []struct {

[stevechuck]

@Nuru Done!

[stevechuck]

/assign @thockin
for approval

[Nuru]

/assign @smarterclayton

The robot assigned thockin but since this fixes a bug you opened (#72292), perhaps you would be interested in reviewing and approving it

[Nuru]

@dashpole Do you want anything more or can we get a LGTM from you?

[dashpole]

nope, thanks for the explanation. This isn't a CRI change, its a kubelet pod logs endpoint change.

/lgtm
for kubelet changes. I'll leave it to @smarterclayton or @derekwaynecarr to approve the sort-of-api-change.

[smarterclayton]

I believe this change is within the spirit of our API guidelines - the precision was variable before, it is unlikely that anyone was successful at hardcoding precision, and while this may change parsing of ReadLog output, the format is broadly worded with no explicit guarantee. Standard timestamp processing would be no more or less impacted in general. I'm willing to chance a very small number of parsing scripts that were subtly wrong are impacted.

/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: iamchuckss, smarterclayton

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:

• pkg/apis/core/OWNERS [smarterclayton]
• pkg/kubelet/OWNERS [smarterclayton]

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

[Nuru]

@smarterclayton Thanks for the approval. What do you think about cherry-picking this back to currently supported releases? I know it is not a critical bug fix, but it is also small and low-risk.

[Nuru]

@iamchuckss Thanks for doing this PR. What do you think of proposing cherry-picks so we can see this sooner rather than later?

[stevechuck]

@Nuru That's fine with me, I can initiate a cherry pick request.

The request has been created at #91351.

[Nuru]

@iamchuckss Thanks. Would you also please cherry pick to 1.17 and 1.16 (and 1.15 if that is still an option)?