Leverage logstream to get better e2e diagnostic logs. #3388

mattmoor · 2020-10-14T18:42:20Z

Changes

logstream is a package that we use in knative to inline the system component logs relevant to a particular test into the test logs. It relies on tests following the auto-naming convention we use with our helper method helpers.ObjectNameForTest(t), which attaches a common prefix to resource names allowing logstream to filter the relevant log lines.

By virtue of using the genreconciler and other knative.dev/pkg controller infrastructure, each reconciler using logging.FromContext(ctx) on the context passed to ReconcileKind already gets a logger that's infused with the "key" being reconciled, but there may be other shared libraries that may require further instrumentation for this to reach its full potential.

I'm instrumenting several tests where I have seen downstream flakes as a start, and hopefully this illuminated why those tests are flaking by shining a light on controller activities during the test's execution.

Submitter Checklist

These are the criteria that every PR should meet, please check them off as you
review them:

Includes tests (if functionality changed/added)
Includes docs (if user facing)
Commit messages follow commit message best practices
Release notes block has been filled in or deleted (only if no user facing changes)

See the contribution guide for more details.

Double check this list of stuff that's easy to miss:

If you are adding a new binary/image to the cmd dir, please update
the release Task to build and release this image.

Reviewer Notes

If API changes are included, additive changes must be approved by at least two OWNERS and backwards incompatible changes must be approved by more than 50% of the OWNERS, and they must first be added in a backwards compatible way.

Release Notes

NONE

/assign @imjasonh @vdemeester @afrittoli

logstream is a package that we use in knative to inline the system component logs relevant to a particular test into the test logs. It relies on tests following the auto-naming convention we use with our helper method `helpers.ObjectNameForTest(t)`, which attaches a common prefix to resource names allowing logstream to filter the relevant log lines. By virtue of using the `genreconciler` and other knative.dev/pkg controller infrastructure, each reconciler using `logging.FromContext(ctx)` on the context passed to `ReconcileKind` already gets a logger that's infused with the "key" being reconciled, but there may be other shared libraries that may require further instrumentation for this to reach its full potential. I'm instrumenting several tests where I have seen downstream flakes as a start, and hopefully this illuminated why those tests are flaking by shining a light on controller activities during the test's execution.

mattmoor · 2020-10-14T18:43:15Z

I may tack on some additional flaky tests here, but I wanted to stage one at a time to check that e2e tests pass (and I'm not making any bad assumptions)

mattmoor · 2020-10-14T18:49:00Z

/kind feature

mattmoor · 2020-10-14T18:49:06Z

/test check-pr-has-kind-label

mattmoor · 2020-10-14T19:10:33Z

First test passed, adding timeout_test.go as well.

imjasonh · 2020-10-14T19:15:12Z

/lgtm

This looks really cool! I think it's going to make debugging flakes a lot simpler, by moving all the relevant information into the same place.

mattmoor · 2020-10-14T19:25:04Z

Yeah, the intent of it was to try and pre-filter, join and interleave all of the relevant logs into t.Log for tests.

It can mean large logs, but it is generally pretty useful.

mattmoor · 2020-10-14T19:26:32Z

I have a couple more queued up that I've seen flake downstream in the last ~24 hours: cancel_test.go and pipelinefinally_test.go.

I'll push a commit for those once the above comes back clean 🤞

mattmoor · 2020-10-14T19:41:53Z

Next one passed. I've pushed two more commits with two more tests. I'll stop there, so we can hopefully checkpoint things and get some better diagnostics from failures 🤞

imjasonh · 2020-10-14T19:46:14Z

/lgtm

afrittoli

This looks good, thank you!
The integration job is still running, once it's done I'll be able to see the difference :)
If we decide to settle for this it would be good to start documenting best practices when writing tests so that new tests will fit this approach.

mattmoor · 2020-10-14T19:59:45Z

@afrittoli yup, for once we documented it in PKG 😅

https://github.com/knative/pkg/blob/master/test/logstream/README.md

mattmoor · 2020-10-14T20:01:19Z

Here's a sample log line from a serving e2e flake:

kubelogs.go:197: I 01:25:17.385 controller-588cb74895-r25bv [configuration-controller] [serving-tests/scale-to-n-scale-200-065-of-200-ekqhpiww] Reconcile succeeded. Time taken: 11.127µs

The format is {level} {timestamp} {pod-name} [{controller name}] [{resource key}] {log-line}

Full test output (that I picked that from): https://prow.knative.dev/view/gcs/knative-prow/logs/ci-knative-serving-contour-latest/1315090891001565185

mattmoor · 2020-10-14T20:02:55Z

I'm not gonna lie either, I partly did this because JSON logs made my eyes bleed outside of something like stackdriver 🤣

mattmoor · 2020-10-14T20:05:23Z

You can start to see it if you crack the raw logs of the running job too:

=== CONT  TestTaskRunPipelineRunCancel/retries=1
    TestTaskRunPipelineRunCancel/retries=0: cancel_test.go:73: Creating PipelineRun in namespace arendelle-9rws9
    TestTaskRunPipelineRunCancel/retries=1: cancel_test.go:73: Creating PipelineRun in namespace arendelle-6p6bp
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] Adding to queue arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml (depth: 1)
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh] Adding to queue arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh (depth: 2)
    TestTaskRunPipelineRunCancel/retries=1: cancel_test.go:78: Waiting for Pipelinerun task-run-pipeline-run-cancel-retries-1-djhhcdvh in namespace arendelle-6p6bp to be started
    TestTaskRunPipelineRunCancel/retries=0: cancel_test.go:78: Waiting for Pipelinerun task-run-pipeline-run-cancel-retries-0-unjegoml in namespace arendelle-9rws9 to be started
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] Adding to queue arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml (depth: 3)
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [pipelinerun/pipelinerun.go:649] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] Creating a new TaskRun object task-run-pipeline-run-cancel-retries-0-unjegoml-task-d6s68
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh] Adding to queue arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh (depth: 3)
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [pipelinerun/pipelinerun.go:649] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh] Creating a new TaskRun object task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml-task-d6s68] Adding to queue arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml-task-d6s68 (depth: 1)
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [taskrun/taskrun.go:322] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml-task-d6s68] Cloud Events: []
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [pipelinerun/pipelinerun.go:495] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] PipelineRun task-run-pipeline-run-cancel-retries-0-unjegoml status is being set to &{Succeeded Unknown  {2020-10-14 19:49:59.214102597 +0000 UTC m=+60.078630826} Running Tasks Completed: 0 (Failed: 0, Cancelled 0), Incomplete: 1, Skipped: 0}
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26] Adding to queue arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26 (depth: 1)
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [taskrun/taskrun.go:322] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26] Cloud Events: []
    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: I 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [pipelinerun/pipelinerun.go:495] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh] PipelineRun task-run-pipeline-run-cancel-retries-1-djhhcdvh status is being set to &{Succeeded Unknown  {2020-10-14 19:49:59.316978857 +0000 UTC m=+60.181507085} Running Tasks Completed: 0 (Failed: 0, Cancelled 0), Incomplete: 1, Skipped: 0}
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] Adding to queue arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml (depth: 3)
    TestTaskRunPipelineRunCancel/retries=0: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [pipelinerun/reconciler.go:322] [arendelle-9rws9/task-run-pipeline-run-cancel-retries-0-unjegoml] Updating status with:   v1beta1.PipelineRunStatus{
          	Status: v1beta1.Status{
          		ObservedGeneration: 0,
        - 		Conditions:         nil,
        + 		Conditions: v1beta1.Conditions{
        + 			{
        + 				Type:               "Succeeded",
        + 				Status:             "Unknown",
        + 				LastTransitionTime: apis.VolatileTime{Inner: s"2020-10-14 19:49:59.214102597 +0"...},
        + 				Reason:             "Running",
        + 				Message:            "Tasks Completed: 0 (Failed: 0, Cancelled 0), Incomplete: 1, Skip"...,
        + 			},
        + 		},
          		Annotations: nil,
          	},
          	PipelineRunStatusFields: v1beta1.PipelineRunStatusFields{
        - 		StartTime:      nil,
        + 		StartTime:      s"2020-10-14 19:49:58.914672461 +0000 UTC m=+59.779200693",
          		CompletionTime: nil,
        - 		TaskRuns:       nil,
        + 		TaskRuns: map[string]*v1beta1.PipelineRunTaskRunStatus{
        + 			"task-run-pipeline-run-cancel-retries-0-unjegoml-task-d6s68": &{PipelineTaskName: "task", Status: &v1beta1.TaskRunStatus{}},
        + 		},
          		PipelineResults: nil,
        - 		PipelineSpec:    nil,
        + 		PipelineSpec: &v1beta1.PipelineSpec{
        + 			Tasks: []v1beta1.PipelineTask{{Name: "task", TaskSpec: &v1beta1.EmbeddedTask{...}, Retries: 1}},
        + 		},
          		SkippedTasks: nil,
          	},
          }

afrittoli

Yeah, this looks really good!
Something that is missing today in logs is a timestamp (this is a separate issue) but you can see it reflected here in the 00:00:00 timestamp:

    TestTaskRunPipelineRunCancel/retries=1: kubelogs.go:197: D 00:00:00.000 tekton-pipelines-controller-68f598fdd7-j7xkj [controller/controller.go:397] [arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26] Adding to queue arendelle-6p6bp/task-run-pipeline-run-cancel-retries-1-djhhcdvh-task-wfj26 (depth: 2)

/approve

tekton-robot · 2020-10-14T20:15:50Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: afrittoli

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~~ [afrittoli]

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

mattmoor · 2020-10-14T20:18:28Z

@afrittoli 😅 yeah I think that's pretty easy to add. You folks don't put timestamps in your logs by default 🤯

afrittoli · 2020-10-14T20:21:19Z

Yeah, I'm not sure why, and every time I forget to make the PR... Will do this time

tekton-robot assigned afrittoli and imjasonh Oct 14, 2020

tekton-robot added the release-note-none Denotes a PR that doesnt merit a release note. label Oct 14, 2020

tekton-robot assigned vdemeester Oct 14, 2020

tekton-robot requested review from dibyom and dlorenc October 14, 2020 18:42

tekton-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Oct 14, 2020

tekton-robot added the kind/feature Categorizes issue or PR as related to a new feature. label Oct 14, 2020

Also instrument timeout_test.go

ad41cfd

tekton-robot added the lgtm Indicates that a PR is ready to be merged. label Oct 14, 2020

mattmoor added 2 commits October 14, 2020 12:40

Also instrument cancel_test.go

ca9be9c

Also instrument piplinefinally_test.go

b700031

tekton-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed lgtm Indicates that a PR is ready to be merged. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Oct 14, 2020

tekton-robot added the lgtm Indicates that a PR is ready to be merged. label Oct 14, 2020

afrittoli reviewed Oct 14, 2020

View reviewed changes

tekton-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 14, 2020

tekton-robot merged commit 2436f0d into tektoncd:master Oct 14, 2020

mattmoor deleted the logstream-a-few branch October 14, 2020 20:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Leverage logstream to get better e2e diagnostic logs. #3388

Leverage logstream to get better e2e diagnostic logs. #3388

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

imjasonh commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

imjasonh commented Oct 14, 2020

afrittoli left a comment

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020 •

edited

Loading

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

afrittoli left a comment

tekton-robot commented Oct 14, 2020

mattmoor commented Oct 14, 2020

afrittoli commented Oct 14, 2020

Leverage logstream to get better e2e diagnostic logs. #3388

Leverage logstream to get better e2e diagnostic logs. #3388

Conversation

mattmoor commented Oct 14, 2020

Changes

Submitter Checklist

Reviewer Notes

Release Notes

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

imjasonh commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

imjasonh commented Oct 14, 2020

afrittoli left a comment

Choose a reason for hiding this comment

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020 • edited Loading

mattmoor commented Oct 14, 2020

mattmoor commented Oct 14, 2020

afrittoli left a comment

Choose a reason for hiding this comment

tekton-robot commented Oct 14, 2020

mattmoor commented Oct 14, 2020

afrittoli commented Oct 14, 2020

mattmoor commented Oct 14, 2020 •

edited

Loading