[Diagnostics] Fix AnalyzeLogs to provide more clear debug message #18654

nak3 · 2018-02-17T04:12:04Z

When we run oc adm diagnostics AnalyzeLogs, diagnostics command
often misses error messsages in journal logs. So, as an admin we are
trying to find out the reason, but debug message gives us unclear
message:

$ oc adm diagnostics AnalyzeLogs -l=0
   ...
debug: Stopped reading docker log: timestamp 1518835107917828 too old
   ...

So, this patch changes regarding AnayzeLogs as:

Output field of struct of discovered systemd unit
Produce correct error message if journal log has invalid timestamp
Output why diagnostics stopped reading logs with readable timestamp.

Here is the message after applied this patch:

debug: Stopped reading docker log: timestamp 2018-02-17 11:33:58 +0900 JST more than 1 hour ago

nak3 · 2018-02-17T04:14:42Z

pkg/oc/admin/diagnostics/diagnostics/cluster/master_node.go

@@ -146,7 +146,7 @@ func resolveServerIP(serverUrl string, fn dnsResolver) ([]string, error) {

 func searchNodesForIP(nodes []kapi.Node, ips []string) types.DiagnosticResult {
 	r := types.NewDiagnosticResult(MasterNodeName)
-	r.Debug("DClu3005", fmt.Sprintf("Seaching for a node with master IP: %s", ips))
+	r.Debug("DClu3005", fmt.Sprintf("Searching for a node with master IP: %s", ips))


This debug message currently shows:

debug: map[origin-node:{origin-node false false false 0} openvswitch:{openvswitch true false true 0} iptables:{iptables true true true 0} docker:{docker true true true 0} etcd:{etcd true true true 0} kubernetes:{kubernetes false false false 0} origin-master:{origin-master false false false 0} atomic-openshift-master:{atomic-openshift-master false false false 0} atomic-openshift-node:{atomic-openshift-node true true true 0}]

Actually I wanted to delete it, but if I deleted it, the number DClu3005 will be absent in master_node.go

There's no special reason to keep an identifier.

But, I think you are talking about the debug statement in locate_units.go

I don't think you need to keep the message just to preserve DClu3005 tag. If the tag is present then it should point to unique error/debug but if the error/debug is not relevant any more then we should delete the error/debug. Don't keep stale code just to maintain these tags (we have done the same thing for networkcheck and aggregatedlogging diagnostics).

We can always pinpoint the error/debug/warning without these tags, we just need ose release (oc version) and filepath:line-number which are available. I think these tags are more confusing than useful. May be we should get rid of them?
@sosiouxme

@pravisankar The tags certainly serve no purpose for debug/info level at this time. The purpose in warn/error is to have something stable and semantically meaningless that's safe to grep in automation, as there is no machine-readable output at this time. The tags were originally intended for machine-readable output, which is a requested and long-neglected feature.

I doubt anyone's using the tags for that purpose now. I suppose overall it may be better to get rid of tags entirely. It would not be hard to retrofit them when fleshing out the machine-readable feature.

I'm sorry, I made a comment under wrong line. As @sosiouxme, I meant logger.Debug("DS1003", fmt.Sprintf("%v", systemdUnits)). (And I removed it now.)

The message DClu3005 is really necessary until this bug was fixed https://bugzilla.redhat.com/show_bug.cgi?id=1368865

nak3 · 2018-02-20T12:32:29Z

cc @sosiouxme

pravisankar

Minor nit otherwise LGTM

pravisankar · 2018-02-20T17:15:24Z

pkg/oc/admin/diagnostics/diagnostics/cluster/master_node.go

@@ -146,7 +146,7 @@ func resolveServerIP(serverUrl string, fn dnsResolver) ([]string, error) {

 func searchNodesForIP(nodes []kapi.Node, ips []string) types.DiagnosticResult {
 	r := types.NewDiagnosticResult(MasterNodeName)
-	r.Debug("DClu3005", fmt.Sprintf("Seaching for a node with master IP: %s", ips))
+	r.Debug("DClu3005", fmt.Sprintf("Searching for a node with master IP: %s", ips))


I don't think you need to keep the message just to preserve DClu3005 tag. If the tag is present then it should point to unique error/debug but if the error/debug is not relevant any more then we should delete the error/debug. Don't keep stale code just to maintain these tags (we have done the same thing for networkcheck and aggregatedlogging diagnostics).

pravisankar · 2018-02-20T17:22:25Z

pkg/oc/admin/diagnostics/diagnostics/cluster/master_node.go

@@ -146,7 +146,7 @@ func resolveServerIP(serverUrl string, fn dnsResolver) ([]string, error) {

 func searchNodesForIP(nodes []kapi.Node, ips []string) types.DiagnosticResult {
 	r := types.NewDiagnosticResult(MasterNodeName)
-	r.Debug("DClu3005", fmt.Sprintf("Seaching for a node with master IP: %s", ips))
+	r.Debug("DClu3005", fmt.Sprintf("Searching for a node with master IP: %s", ips))


We can always pinpoint the error/debug/warning without these tags, we just need ose release (oc version) and filepath:line-number which are available. I think these tags are more confusing than useful. May be we should get rid of them?
@sosiouxme

sosiouxme

Thanks for fixing this up. I have some requests and then we can merge this.

BTW, the log analysis doesn't check many patterns yet -- if there are useful log entries you'd like this to find for you, please suggest those or add a PR...

sosiouxme · 2018-02-20T17:06:46Z

pkg/oc/admin/diagnostics/diagnostics/cluster/master_node.go

@@ -146,7 +146,7 @@ func resolveServerIP(serverUrl string, fn dnsResolver) ([]string, error) {

 func searchNodesForIP(nodes []kapi.Node, ips []string) types.DiagnosticResult {
 	r := types.NewDiagnosticResult(MasterNodeName)
-	r.Debug("DClu3005", fmt.Sprintf("Seaching for a node with master IP: %s", ips))
+	r.Debug("DClu3005", fmt.Sprintf("Searching for a node with master IP: %s", ips))


There's no special reason to keep an identifier.

But, I think you are talking about the debug statement in locate_units.go

sosiouxme · 2018-02-20T17:22:44Z

pkg/oc/admin/diagnostics/diagnostics/systemd/analyze_logs.go

@@ -99,8 +99,13 @@ func (d AnalyzeLogs) Check() types.DiagnosticResult {
 					if err := json.Unmarshal(bytes, &entry); err != nil {
 						r.Debug("DS0003", fmt.Sprintf("Couldn't read the JSON for this log message:\n%s\nGot error %s", string(bytes), errStr(err)))
 					} else {
-						if lineCount > 500 && stampTooOld(entry.TimeStamp, timeLimit) {
-							r.Debug("DS0004", fmt.Sprintf("Stopped reading %s log: timestamp %s too old", unitName, entry.TimeStamp))
+						old, unixTimestamp, err := stampTooOld(entry.TimeStamp, timeLimit)


I have a few suggestions to make here.

stampTooOld is only ever used here. All it really accomplishes is making this logic easy to understand. Here you've turned the method into trinary logic (true/false/error) plus return value and then you have to process that trinary again upon receiving it. I think it would be simpler just to bring the method inline and use loop controls rather than return.

sosiouxme · 2018-02-20T17:30:23Z

pkg/oc/admin/diagnostics/diagnostics/systemd/analyze_logs.go

+						old, unixTimestamp, err := stampTooOld(entry.TimeStamp, timeLimit)
+						if err != nil {
+							r.Error("DS0004", err, fmt.Sprintf("Stopped reading %s log, timestamp %s is invalid", unitName, entry.TimeStamp))
+							break


Subtle difference here. This will end the loop the first time it sees a malformed log line (if that ever happens! not sure I've ever seen it). Previously it would only end the loop if there was an error and it had seen more than 500 lines.

It would make more sense to me to skip the log line with a continue here and keep looking.

sosiouxme · 2018-02-21T15:16:17Z

https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/18654/test_pull_request_origin_extended_networking_minimal/14564/ is flake #11315
https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/18654/test_pull_request_origin_extended_conformance_gce/16550/ is new flake #18695
/retest
/lgtm

openshift-ci-robot · 2018-02-21T15:16:22Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: nak3, sosiouxme

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

Needs approval from an approver in each of these OWNERS Files:

~~pkg/oc/admin/diagnostics/diagnostics/OWNERS~~ [sosiouxme]

You can indicate your approval by writing /approve in a comment
You can cancel your approval by writing /approve cancel in a comment

openshift-bot · 2018-02-21T16:22:36Z

/retest

Please review the full test history for this PR and help us cut down flakes.

sosiouxme · 2018-02-21T18:04:38Z

https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/18654/test_pull_request_origin_extended_networking_minimal/14578/ is #11315 again
/retest

openshift-merge-robot · 2018-02-21T19:12:35Z

/test all [submit-queue is verifying that this PR is safe to merge]

openshift-merge-robot · 2018-02-21T20:42:45Z

Automatic merge from submit-queue.

nak3 · 2018-02-22T00:19:11Z

Thank you. I think I should have squashed these commits, before merge. (I'm sorry!)

sosiouxme · 2018-02-22T14:09:35Z

That does make life easier when doing a git bisect, but otherwise isn't really that important, so don't worry about it.

openshift-ci-robot requested review from pravisankar and smarterclayton February 17, 2018 04:12

openshift-ci-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Feb 17, 2018

nak3 commented Feb 17, 2018

View reviewed changes

pravisankar reviewed Feb 20, 2018

View reviewed changes

sosiouxme reviewed Feb 20, 2018

View reviewed changes

nak3 added 4 commits February 21, 2018 18:51

Fix typo Seaching to Searching

315fdf1

Fix AnalyzeLogs to provide more clear debug message

011e0aa

Output field of struct of discovered systemd unit

34bea5e

Move stampTooOld into Check function

8adfb26

openshift-ci-robot assigned sosiouxme Feb 21, 2018

openshift-ci-robot added the lgtm Indicates that a PR is ready to be merged. label Feb 21, 2018

openshift-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Feb 21, 2018

openshift-merge-robot merged commit 37a4ec3 into openshift:master Feb 21, 2018

nak3 deleted the diagnostics branch February 22, 2018 00:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Diagnostics] Fix AnalyzeLogs to provide more clear debug message #18654

[Diagnostics] Fix AnalyzeLogs to provide more clear debug message #18654

nak3 commented Feb 17, 2018

nak3 Feb 17, 2018

sosiouxme Feb 20, 2018

pravisankar Feb 20, 2018

pravisankar Feb 20, 2018

sosiouxme Feb 20, 2018 •

edited

Loading

nak3 Feb 21, 2018

nak3 commented Feb 20, 2018

pravisankar left a comment

pravisankar Feb 20, 2018

pravisankar Feb 20, 2018

sosiouxme left a comment

sosiouxme Feb 20, 2018

sosiouxme Feb 20, 2018

sosiouxme Feb 20, 2018

sosiouxme commented Feb 21, 2018

openshift-ci-robot commented Feb 21, 2018

openshift-bot commented Feb 21, 2018

sosiouxme commented Feb 21, 2018

openshift-merge-robot commented Feb 21, 2018

openshift-merge-robot commented Feb 21, 2018

nak3 commented Feb 22, 2018

sosiouxme commented Feb 22, 2018

[Diagnostics] Fix AnalyzeLogs to provide more clear debug message #18654

[Diagnostics] Fix AnalyzeLogs to provide more clear debug message #18654

Conversation

nak3 commented Feb 17, 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

sosiouxme Feb 20, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nak3 commented Feb 20, 2018

pravisankar left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sosiouxme 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

sosiouxme commented Feb 21, 2018

openshift-ci-robot commented Feb 21, 2018

openshift-bot commented Feb 21, 2018

sosiouxme commented Feb 21, 2018

openshift-merge-robot commented Feb 21, 2018

openshift-merge-robot commented Feb 21, 2018

nak3 commented Feb 22, 2018

sosiouxme commented Feb 22, 2018

sosiouxme Feb 20, 2018 •

edited

Loading