Detect kubelet and container runtime frequent restarts #223

wangzhen127 · 2018-11-20T21:53:31Z

This PR adds customer plugin that watch systemd logs for frequent kubelet and container runtime restarts. It reuses log counter for frequent restart detection. Notice that kubelet and container runtime restart logs are actually in systemd logs, not in kubelet or container runtime logs.

Noticeable changes:

Add delay option to log watchers, so that they can delay watching until the node is stable.
Change log counter to watch journald instead of kmsg.
Update docker monitor to use dockerd as the source name.
Fix vet errors
Update README on injecting systemd logs

wangzhen127 · 2018-11-20T21:54:23Z

/assign @Random-Liu
/cc @dashpole
/cc @jiayingz

wangzhen127 · 2018-11-21T21:17:39Z

@Random-Liu, I have updated this PR with delay option. PTAL

Random-Liu · 2018-11-21T21:59:03Z

cmd/logcounter/options/options.go

 }

 // AddFlags adds log counter command line options to pflag.
 func (fedo *LogCounterOptions) AddFlags(fs *pflag.FlagSet) {
+	fs.StringVar(&fedo.JournaldSource, "journald-source", "", "The source configuration of journald, e.g., kernel, kubelet, docker, etc")


s/docker/dockerd?

Random-Liu · 2018-11-21T21:59:32Z

cmd/logcounter/options/options.go

 	fs.StringVar(&fedo.Lookback, "lookback", "", "The time log watcher looks up")
+	fs.StringVar(&fedo.Delay, "delay", "", "The time duration log watcher delays after node boot time")


Add a bit more explanation here?

Random-Liu · 2018-11-21T22:04:34Z

pkg/systemlogmonitor/logwatchers/filelog/log_watcher.go

-		glog.Fatalf("Failed to get system info: %v", err)
+	startTime, err := util.GetDelayedStartTime(cfg.Delay)
+	if err != nil {
+		glog.Fatalf("%v", err)


Make the error log more informative: "failed to get xxx"

Random-Liu · 2018-11-21T22:05:38Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

 }

 // NewJournaldWatcher is the create function of journald watcher.
 func NewJournaldWatcher(cfg types.WatcherConfig) types.LogWatcher {
+	startTime, err := util.GetDelayedStartTime(cfg.Delay)
+	if err != nil {
+		glog.Fatalf("%v", err)


Random-Liu · 2018-11-21T22:06:22Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

-	if lookback > uptime {
-		lookback = uptime
-		glog.Infof("Lookback changed to system uptime: %v", lookback)
-	}
 	// Seek journal client based on the lookback duration.
 	start := time.Now().Add(-lookback)


Why not use this?

Now considering lookback when getting start time.

Random-Liu · 2018-11-21T22:09:00Z

pkg/util/helpers.go

@@ -31,3 +32,23 @@ func GenerateConditionChangeEvent(t string, status types.ConditionStatus, reason
 		Message:   fmt.Sprintf("Node condition %s is now: %s, reason: %s", t, status, reason),
 	}
 }
+
+func GetDelayedStartTime(delay string) (time.Time, error) {


I feel like this can be combined with lookback, just pass in both delay and lookback, and return starttime.

Random-Liu · 2018-11-21T22:13:00Z

config/systemd-monitor-counter.json

+        "--log-path=/var/log/journal",
+        "--lookback=20m",
+        "--count=5",
+        "--pattern=Starting Docker Application Container Engine..."


Why use Starting for docker and containerd, but Started for kubelet? Any particular reason?

Because there is no Starting message for kubelet.

Hm, interesting.

wangzhen127

@Random-Liu, I have updated this PR. PTAL.

wangzhen127 · 2018-11-22T00:19:43Z

cmd/logcounter/options/options.go

 }

 // AddFlags adds log counter command line options to pflag.
 func (fedo *LogCounterOptions) AddFlags(fs *pflag.FlagSet) {
+	fs.StringVar(&fedo.JournaldSource, "journald-source", "", "The source configuration of journald, e.g., kernel, kubelet, docker, etc")


wangzhen127 · 2018-11-22T00:21:19Z

cmd/logcounter/options/options.go

 	fs.StringVar(&fedo.Lookback, "lookback", "", "The time log watcher looks up")
+	fs.StringVar(&fedo.Delay, "delay", "", "The time duration log watcher delays after node boot time")


wangzhen127 · 2018-11-22T00:22:01Z

config/systemd-monitor-counter.json

+        "--log-path=/var/log/journal",
+        "--lookback=20m",
+        "--count=5",
+        "--pattern=Starting Docker Application Container Engine..."


Because there is no Starting message for kubelet.

wangzhen127 · 2018-11-22T00:25:58Z

pkg/systemlogmonitor/logwatchers/filelog/log_watcher.go

-		glog.Fatalf("Failed to get system info: %v", err)
+	startTime, err := util.GetDelayedStartTime(cfg.Delay)
+	if err != nil {
+		glog.Fatalf("%v", err)


wangzhen127 · 2018-11-22T00:26:05Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

 }

 // NewJournaldWatcher is the create function of journald watcher.
 func NewJournaldWatcher(cfg types.WatcherConfig) types.LogWatcher {
+	startTime, err := util.GetDelayedStartTime(cfg.Delay)
+	if err != nil {
+		glog.Fatalf("%v", err)


wangzhen127 · 2018-11-22T09:40:09Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

-	if lookback > uptime {
-		lookback = uptime
-		glog.Infof("Lookback changed to system uptime: %v", lookback)
-	}
 	// Seek journal client based on the lookback duration.
 	start := time.Now().Add(-lookback)


Now considering lookback when getting start time.

wangzhen127 · 2018-11-22T09:40:19Z

pkg/util/helpers.go

@@ -31,3 +32,23 @@ func GenerateConditionChangeEvent(t string, status types.ConditionStatus, reason
 		Message:   fmt.Sprintf("Node condition %s is now: %s, reason: %s", t, status, reason),
 	}
 }
+
+func GetDelayedStartTime(delay string) (time.Time, error) {


wangzhen127 · 2018-11-22T09:58:28Z

/retest

wangzhen127 · 2018-11-22T10:16:13Z

Rebased

wangzhen127 · 2018-11-26T23:27:50Z

Just tested on a GKE node and it works.

Random-Liu

LGTM with nits

Random-Liu · 2018-11-27T00:51:45Z

pkg/systemlogmonitor/logwatchers/filelog/log_watcher.go

-		if s.clock.Since(log.Timestamp) > lookback || log.Timestamp.Before(s.uptime) {
+		// Discard messages before start time.
+		if log.Timestamp.Before(s.startTime) {
+			glog.V(5).Infof("Throwing away msg %v before start time: %v < %v", log.Message, log.Timestamp, s.startTime)


Random-Liu · 2018-11-27T00:55:53Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

@@ -112,6 +124,11 @@ func (j *journaldWatcher) watchLoop() {
 			continue
 		}

+		if entry.RealtimeTimestamp < startTimestamp {
+			glog.V(5).Infof("Throwing away journal entry before start time: %v < %v", entry.RealtimeTimestamp, startTimestamp)


Include message content?

Random-Liu · 2018-11-27T00:56:39Z

pkg/systemlogmonitor/logwatchers/kmsg/log_watcher.go

-				glog.V(5).Infof("Throwing away msg %v for being too old: %v > %v", msg.Message, msg.Timestamp.String(), lookback.String())
+			// Discard messages before start time.
+			if msg.Timestamp.Before(k.startTime) {
+				glog.V(5).Infof("Throwing away msg %v before start time: %v < %v", msg.Message, msg.Timestamp, k.startTime)


wangzhen127

Updated. PTAL

wangzhen127 · 2018-11-27T06:33:47Z

pkg/systemlogmonitor/logwatchers/filelog/log_watcher.go

-		if s.clock.Since(log.Timestamp) > lookback || log.Timestamp.Before(s.uptime) {
+		// Discard messages before start time.
+		if log.Timestamp.Before(s.startTime) {
+			glog.V(5).Infof("Throwing away msg %v before start time: %v < %v", log.Message, log.Timestamp, s.startTime)


wangzhen127 · 2018-11-27T06:39:17Z

pkg/systemlogmonitor/logwatchers/journald/log_watcher.go

@@ -112,6 +124,11 @@ func (j *journaldWatcher) watchLoop() {
 			continue
 		}

+		if entry.RealtimeTimestamp < startTimestamp {
+			glog.V(5).Infof("Throwing away journal entry before start time: %v < %v", entry.RealtimeTimestamp, startTimestamp)


wangzhen127 · 2018-11-27T06:39:36Z

pkg/systemlogmonitor/logwatchers/kmsg/log_watcher.go

-				glog.V(5).Infof("Throwing away msg %v for being too old: %v > %v", msg.Message, msg.Timestamp.String(), lookback.String())
+			// Discard messages before start time.
+			if msg.Timestamp.Before(k.startTime) {
+				glog.V(5).Infof("Throwing away msg %v before start time: %v < %v", msg.Message, msg.Timestamp, k.startTime)


Random-Liu · 2018-11-27T08:31:40Z

/lgtm

Random-Liu · 2018-11-27T08:32:12Z

/approve

k8s-ci-robot · 2018-11-27T08:32:21Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: Random-Liu, wangzhen127

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:

~~OWNERS~~ [Random-Liu]

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 added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Nov 20, 2018

k8s-ci-robot requested review from andyxning and dchen1107 November 20, 2018 21:53

k8s-ci-robot assigned Random-Liu Nov 20, 2018

k8s-ci-robot requested review from dashpole and jiayingz November 20, 2018 21:54

wangzhen127 force-pushed the kubelet-crash branch from b1cd976 to b398d5f Compare November 20, 2018 22:19

wangzhen127 changed the title ~~Detect kubelet and container runtime frequent crashes~~ Detect kubelet and container runtime frequent restarts Nov 20, 2018

wangzhen127 mentioned this pull request Nov 21, 2018

Detect corrupt docker overlay2 #224

Merged

wangzhen127 force-pushed the kubelet-crash branch 2 times, most recently from ea26527 to aa53d4c Compare November 21, 2018 21:15

Random-Liu reviewed Nov 21, 2018

View reviewed changes

wangzhen127 force-pushed the kubelet-crash branch from aa53d4c to a7b6902 Compare November 22, 2018 09:40

k8s-ci-robot added size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. and removed size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Nov 22, 2018

wangzhen127 force-pushed the kubelet-crash branch from a7b6902 to 48cfb6d Compare November 22, 2018 09:50

wangzhen127 commented Nov 22, 2018

View reviewed changes

wangzhen127 force-pushed the kubelet-crash branch from 48cfb6d to e5ccf98 Compare November 22, 2018 10:04

Random-Liu reviewed Nov 27, 2018

View reviewed changes

Detect kubelet and container runtime frequent crashes

1f63638

wangzhen127 force-pushed the kubelet-crash branch from e5ccf98 to 1f63638 Compare November 27, 2018 06:48

wangzhen127 commented Nov 27, 2018

View reviewed changes

k8s-ci-robot added lgtm "Looks good to me", indicates that a PR is ready to be merged. approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Nov 27, 2018

k8s-ci-robot merged commit e807235 into kubernetes:master Nov 27, 2018

wangzhen127 deleted the kubelet-crash branch November 27, 2018 08:35

SergeyKanzhelev mentioned this pull request Aug 4, 2021

FrequentDockerRestart rule fine tuning #603

Closed

		fs.StringVar(&fedo.Lookback, "lookback", "", "The time log watcher looks up")
		fs.StringVar(&fedo.Delay, "delay", "", "The time duration log watcher delays after node boot time")

Detect kubelet and container runtime frequent restarts #223

Detect kubelet and container runtime frequent restarts #223

Conversation

wangzhen127 commented Nov 20, 2018 • edited Loading

wangzhen127 commented Nov 20, 2018

wangzhen127 commented Nov 21, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wangzhen127 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wangzhen127 commented Nov 22, 2018

wangzhen127 commented Nov 22, 2018

wangzhen127 commented Nov 26, 2018

Random-Liu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wangzhen127 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Random-Liu commented Nov 27, 2018

Random-Liu commented Nov 27, 2018

k8s-ci-robot commented Nov 27, 2018

wangzhen127 commented Nov 20, 2018 •

edited

Loading