Dynamically configure verbose logging #4311

0xmichalis · 2017-09-01T09:28:13Z

Unify enabling verbose logging across the main prow
workhorses and add missing logging calls in Jenkins
and Slack clients.

Tested this with tide and it works like a charm.

/assign spxtr

spxtr · 2017-09-06T22:56:12Z

prow/config.yaml

@@ -1,6 +1,7 @@
 plank:
  job_url_template: 'https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/{{if eq .Spec.Type "presubmit"}}pr-logs/pull{{else if eq .Spec.Type "batch"}}pr-logs/pull{{else}}logs{{end}}{{if ne .Spec.Refs.Org ""}}{{if ne .Spec.Refs.Org "kubernetes"}}/{{.Spec.Refs.Org}}_{{.Spec.Refs.Repo}}{{else if ne .Spec.Refs.Repo "kubernetes"}}/{{.Spec.Refs.Repo}}{{end}}{{end}}{{if eq .Spec.Type "presubmit"}}/{{with index .Spec.Refs.Pulls 0}}{{.Number}}{{end}}{{else if eq .Spec.Type "batch"}}/batch{{end}}/{{.Spec.Job}}/{{.Status.BuildID}}/'
  report_template: '[Full PR test history](https://k8s-gubernator.appspot.com/pr/{{if eq .Spec.Refs.Org "kubernetes"}}{{if eq .Spec.Refs.Repo "kubernetes"}}{{else}}{{.Spec.Refs.Repo}}/{{end}}{{else}}{{.Spec.Refs.Org}}_{{.Spec.Refs.Repo}}/{{end}}{{with index .Spec.Refs.Pulls 0}}{{.Number}}{{end}}). [Your PR dashboard](https://k8s-gubernator.appspot.com/pr/{{with index .Spec.Refs.Pulls 0}}{{.Author}}{{end}}). Please help us cut down on flakes by [linking to](https://github.com/kubernetes/community/blob/master/contributors/devel/flaky-tests.md#filing-issues-for-flaky-tests) an [open issue](https://github.com/{{.Spec.Refs.Org}}/{{.Spec.Refs.Repo}}/issues?q=is:issue+is:open) when you hit one in your PR.'
+  enable_verbose_log: false


I think it can just be called "verbose_log"

spxtr · 2017-09-06T22:56:54Z

prow/config/config.go

@@ -57,6 +57,8 @@ type Tide struct {
 	// These must be valid GitHub search queries. They should not overlap,
 	// which is to say two queries should never return the same PR.
 	Queries []string `json:"queries,omitempty"`
+	// EnableVerboseLog enables verbose logging for tide dynamically.
+	EnableVerboseLog bool `json:"enable_verbose_log,omitempty"`


Do we want one "verbose_log" config option for all of prow, or an individual option for each component?

Good question, I thought about this and don't feel strong in any way.

Single option:

We don't bloat the config.

Easy to use when you want to debug an event e2e.

Each component has its own:

Finer-grained logging. We may want to run hook with high verbosity and jenkins-operator turned off.

I am willing to try out the single option now that I have layed out my thoughts on the pros of each side. Looking back at hook logging, it feels to me that high verbosity on it is not necessary by default.

Hrm, re hook it's not possible to force it update its client w/o hacking in it a bit more so it's left on by default for now.

0xmichalis · 2017-09-11T17:53:36Z

@spxtr any more comments here?

spxtr · 2017-09-11T20:27:50Z

I have mixed feelings about this one. Reaching in and setting the clients' Logger fields seems fragile. If, for instance, the tide controller decided to say c.kc = c.kc.Namespace("some-other-ns") then it would stop getting logging updates. This is probably not going to happen, but it reflects poorly on the design.

I haven't thought up a better way, though.

0xmichalis · 2017-09-11T21:33:15Z

It's not any different from today, is it? Rewritting the client is going to break any option that is set during initialization. I think this is the simplest and cleanest solution we can get right now for dynamic logging and I would really like to have it as an option when things go south.

Related discussion in kubernetes/kubernetes#39758.

spxtr · 2017-09-11T21:50:46Z

I guess one alternative is to have everything use the standard logger instead of setting c.Logger. Then, when the config.Agent reloads the config it can set the default logger level.

I'm okay with this PR as well, though. Just not super excited about it.

0xmichalis · 2017-09-21T10:51:51Z

I guess one alternative is to have everything use the standard logger instead of setting c.Logger. Then, when the config.Agent reloads the config it can set the default logger level.

We don't use different log levels as much today and I am more interested in disabling logging altogether, or more precisely enable logging when I want to debug something. Or we could change the client loggers to always print in debugging mode. Then, your suggestion makes sense. Thoughts?

0xmichalis · 2017-09-21T13:11:09Z

@spxtr updated as per your suggestion. Feels cleaner indeed.

spxtr

Nice, this looks great. Minor comments.

spxtr · 2017-09-21T16:56:11Z

prow/config/config.go

@@ -53,6 +54,10 @@ type Config struct {
 	// Defaults to "default".
 	PodNamespace string `json:"pod_namespace,omitempty"`

+	// LogLevel enables dynamically updating the log level of the
+	// standard logger that is used by all prow components.
+	LogLevel string `json:"log_level,omitempty"`


Somehow indicate that it must be one of these. Maybe just explicitly list them here?

spxtr · 2017-09-21T16:57:12Z

prow/config/config.go

+
+	level := logrus.InfoLevel
+	if lvl, err := logrus.ParseLevel(c.LogLevel); err != nil {
+		logrus.Warningf("Cannot parse log level, will default to 'info': %v", err)


Propagate up the error rather than allowing it by, and special-case empty string to mean logrus.InfoLevel.

spxtr · 2017-09-21T17:00:58Z

prow/cmd/jenkins-operator/main.go

+	logger := logrus.StandardLogger()
+	kc.Logger = logger.WithField("client", "kube")
+	jc.Logger = logger.WithField("client", "jenkins")
+	ghc.Logger = logger.WithField("client", "github")


It may be worth putting gc.logger = logrus.StandardLogger().WithField("client", "github") into github.NewClient. The Logger field doesn't really need to be public, and this helps make sure that things are consistent going forward.

I'd be okay with that happening in a separate PR.

Yeah, separate PR.

spxtr · 2017-09-22T15:53:46Z

Great stuff, thanks.

/lgtm

k8s-ci-robot · 2017-09-22T16:02:15Z

@Kargakis: I updated Prow config for you!

In response to this:

Unify enabling verbose logging across the main prow
workhorses and add missing logging calls in Jenkins
and Slack clients.

Tested this with tide and it works like a charm.

/assign spxtr

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.

0xmichalis requested review from krzyzacy and spxtr as code owners September 1, 2017 09:28

k8s-ci-robot assigned spxtr Sep 1, 2017

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 Sep 1, 2017

spxtr reviewed Sep 6, 2017

View reviewed changes

0xmichalis added the area/prow Issues or PRs related to prow label Sep 8, 2017

spxtr reviewed Sep 21, 2017

View reviewed changes

Dynamically configure log level in prow

6b16614

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Sep 22, 2017

0xmichalis merged commit ffe9f34 into kubernetes:master Sep 22, 2017

0xmichalis deleted the unify-verbose-logging branch September 22, 2017 16:02

0xmichalis mentioned this pull request Nov 1, 2017

Setup logging inside clients #5295

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Dynamically configure verbose logging #4311

Dynamically configure verbose logging #4311

0xmichalis commented Sep 1, 2017

spxtr Sep 6, 2017

0xmichalis Sep 7, 2017

spxtr Sep 6, 2017

0xmichalis Sep 7, 2017

0xmichalis Sep 7, 2017

0xmichalis commented Sep 11, 2017

spxtr commented Sep 11, 2017

0xmichalis commented Sep 11, 2017

spxtr commented Sep 11, 2017

0xmichalis commented Sep 21, 2017

0xmichalis commented Sep 21, 2017

spxtr left a comment

spxtr Sep 21, 2017

0xmichalis Sep 22, 2017

spxtr Sep 21, 2017

0xmichalis Sep 22, 2017

spxtr Sep 21, 2017

0xmichalis Sep 22, 2017

spxtr commented Sep 22, 2017

k8s-ci-robot commented Sep 22, 2017

Dynamically configure verbose logging #4311

Dynamically configure verbose logging #4311

Conversation

0xmichalis commented Sep 1, 2017

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

0xmichalis commented Sep 11, 2017

spxtr commented Sep 11, 2017

0xmichalis commented Sep 11, 2017

spxtr commented Sep 11, 2017

0xmichalis commented Sep 21, 2017

0xmichalis commented Sep 21, 2017

spxtr 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

spxtr commented Sep 22, 2017

k8s-ci-robot commented Sep 22, 2017