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.

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

Fix kubelet log timestamps #213

Merged
merged 2 commits into from
Feb 2, 2021
Merged

Conversation

jsirianni
Copy link
Member

Kubelet logs are retrieved from Journald because it is the only process that runs on the host (unlike the api, controller, manager processes that run as containers). This causes the kubelet's logging package (glog) to use the timestamp the host is set. In our test environments, this is EST. Containers are set to UTC, so the glog messages given by the other core services use the correct timestamps. Additionally, the agent is running within a container so it can assume that timestamps retrieved from /var/log/containers are using the same timezone as itself.

Log entry from a system set to EST time (this log shows up in the destination 5 hours in the past)

# journalctl -f | grep kubelet

Feb 02 14:14:03 kube-116-c2-w-1 kubelet[1152]: E0202 14:14:03.962817    1152 pod_workers.go:191] Error syncing pod 330969b8-02fc-4e10-bd26-b49d1862d601 ("recommendationservice-69c56b74d4-2psmb_default(330969b8-02fc-4e10-bd26-b49d1862d601)"), skipping: failed to "StartContainer" for "server" with CrashLoopBackOff: "back-off 5m0s restarting failed container=server pod=recommendationservice-69c56b74d4-2psmb_default(330969b8-02fc-4e10-bd26-b49d1862d601)"

Journalctl output has two timestamps

  • journalctl time: Feb 02 14:14:03
  • glog message time: 14:14:03.962817

The log agent is running in a container, with UTC time. Because the timestamp in the glog message does not include a timezone, the agent assumes UTC (which is five hours in the past).

E0202 14:14:03.962817    1152 pod_workers.go:191] Error sync . . . .

The Journald operator solves this by requesting UTC timestamps

// Export logs in UTC time
args = append(args, "--utc")

Because the journald timestamp is within miliseconds of the glog timestamp, I think we should just use what journald gives us and ignore the time stamp parsed from the actual message field (glog message). This required two changes

  • add a message parser specifically for kubelet, rename timestamp field to drop_time to not overwrite the timestamp field already set by journald input
  • drop the drop_time field with a restructure operation

The alternative approach woudl be to give the user the option of setting a kubelet_timezone parameter. I think this adds unnecessary complication when we already have a reliable time source (asking journald to provide UTC).

I have a test environment setup that can quickly replicate this, if anyone wants to hop on a call.

…t logs. kubelet logs will take the timestamp of the host, which will not always be UTC, causing log messages to show up early / late depending on the timezone difference.
Copy link
Contributor

@ericwholt ericwholt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we are adding message_regex_parser_kubelet. Perhaps we should move message_regex_parser up to around line 170 after glogs_parser_router.

@jsirianni
Copy link
Member Author

Since we are adding message_regex_parser_kubelet. Perhaps we should move message_regex_parser up to around line 170 after glogs_parser_router.

done

@jsirianni jsirianni requested a review from ericwholt February 2, 2021 21:07
@jsirianni jsirianni merged commit 25fe124 into master Feb 2, 2021
@jsirianni jsirianni deleted the kubernetes-cluster-kubelet-timezone branch February 2, 2021 21:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants