Use logrus for structured logging #416

ankushagarwal · 2018-02-27T16:45:24Z

Move from glog to sirupsen/logrus for logging
Add a new flag json_log_format
Refactor all log statements to use logrus
Use Info level for log level V(1) and below
Use Debug level for log level V(2) and above
Tested locally

Addresses #24

Sample logs

{"filename":"app/server.go:54","level":"info","msg":"EnvKubeflowNamespace not set, use default namespace","time":"2018-02-27T18:25:18-08:00"}
{"filename":"app/server.go:59","level":"info","msg":"[Version: 0.3.0+git Git SHA: Not provided. Go Version: go1.9.3 Go OS/Arch: darwin/amd64]","time":"2018-02-27T18:25:18-08:00"}
{"filename":"app/server.go:145","level":"info","msg":"No controller_config_file provided; using empty config.","time":"2018-02-27T18:25:18-08:00"}
{"filename":"controller/controller.go:110","level":"info","msg":"Setting up event handlers","time":"2018-02-27T18:25:18-08:00"}

This change is

jlewi · 2018-02-28T02:17:59Z

nit: Could you include some sample log output in the PR description?

jlewi · 2018-02-28T02:19:34Z

Does the log output include line number or just filename?

ankushagarwal · 2018-02-28T02:26:27Z

Added sample log output.

The log output includes line numbers as well.

gaocegege · 2018-02-28T02:34:37Z

Thanks for your contribution 🎉

There is two concerns:

Will vendor's log be printed? Most of components in k8s uses glog, for example, https://github.com/kubeflow/tf-operator/blob/master/vendor/k8s.io/apimachinery/pkg/api/meta/meta.go#L596.
Should we update the code in client/ manually to keep it use logrus instead of glog? The generated code uses glog by default.

gaocegege · 2018-02-28T03:27:31Z

/retest

jlewi · 2018-02-28T13:59:17Z

/assign jlewi
/assign @gaocegege

jlewi · 2018-02-28T14:04:10Z

@gaocegege That's a good point about vendor and generated code. I don't think we should try to update those packages manually; that seems like a burden to maintain long term.

I think it should be fine to intersperse json and not json log entries. Hopefully logging backends are sophisticated enough to deal with this.

The motivation for using structured logging is so that we can add fields to the log from our code so that we can easily search for logs pertaining to a particular job, replica, index, etc... I think this will really help us to debug issues.

A lot of the bugs we get are of the form I expected X to happen for job Y but it did not. So we'd like to know what the operator was doing for job Y. But if a lot of jobs are running finding the relevant logs for a particular job can be diffcult.

@ankushagarwal Can you open up a follow on issue to add such labels to the operator.

ankushagarwal · 2018-02-28T16:45:47Z

Created #424

* Move from glog to sirupsen/logrus for logging * Add a new flag json_log_format * Refactor all log statements to use logrus * Use Info level for log level V(1) and below * Use Debug level for log level V(2) and above Addresses #24

jlewi · 2018-02-28T23:16:56Z

I'd suggest resyncing to see if that fixes the tests.
/lgtm
/hold
Lets wait for @gaocegege to review

ankushagarwal · 2018-02-28T23:46:00Z

/retest

gaocegege · 2018-03-01T01:35:20Z

I will have a try and submit my review today.

gaocegege

@ankushagarwal

There are somethings:

Code in pkg/clientset is changed in the PR, and I think we should not do it manually, so please revert the changes by ./hack/update-codegen.sh
tf-operator -version returns some useless logs

./tf-operator -version         
{"filename":"app/server.go:54","level":"info","msg":"EnvKubeflowNamespace not set, use default namespace","time":"2018-03-01T09:57:27+08:00"}
{"filename":"app/server.go:59","level":"info","msg":"[Version: 0.3.0+git Git SHA: Not provided. Go Version: go1.8.3 Go OS/Arch: linux/amd64]","time":"2018-03-01T09:57:27+08:00"}
Version: 0.3.0+git
Git SHA: Not provided.
Go Version: go1.8.3
Go OS/Arch: linux/amd64

It is ok to ignore the second one since it is not in high priority.

gaocegege · 2018-03-01T02:26:18Z

I have observation to share with you @ankushagarwal @jlewi , I am not sure how to deal with it.

Now we use flag package to support command line flags, and glog also uses it by default. Then you can see our binary have more flags than we thing although we use logrus instead of glog:

➜  tf-operator git:(416) ✗ ./tf-operator -h               
Usage of ./tf-operator:
  -alsologtostderr
    	log to standard error as well as files
  -chaos-level int
    	DO NOT USE IN PRODUCTION - level of chaos injected into the TFJob created by the operator. (default -1)
  -controller-config-file string
    	Path to file containing the controller config.
  -gc-interval duration
    	GC interval (default 10m0s)
  -json-log-format
    	Set true to use json style log format. Set false to use plaintext style log format (default true)
  -log_backtrace_at value
    	when logging hits line file:N, emit a stack trace
  -log_dir string
    	If non-empty, write log files in this directory
  -logtostderr
    	log to standard error instead of files
  -stderrthreshold value
    	logs at or above this threshold go to stderr
  -v value
    	log level for V logs
  -version
    	Show version and quit
  -vmodule value
    	comma-separated list of pattern=N settings for file-filtered logging

There are some pros and cons:

We can support vendor and client's glog, since we have glog's flags
But the users may be confused since the tf-operator outputs logs regardless of the flag -logtostderr

We could discuss it in the issue, not in the PR. After the client is regenerated the PR LGTM

ankushagarwal · 2018-03-01T02:34:03Z

@gaocegege I have changed pkg/client/clientset/versioned/clientset.go which does not seem to have auto generated. Also looks like ./hack/update-codegen.sh is broken

I have fixed the -version logging issue.

gaocegege · 2018-03-01T02:42:51Z

/approve

@ankushagarwal

pkg/client is all auto-generated by kubernetes/code-generator.

update-codegen.sh works for me, it seems that the script uses the wrong code-generator in kubernetes repo.

But no worry about it, I can open a PR to fix the clientset.

Thanks for your awesome contribution and patience! The log problem has been bothering us for long time.

k8s-ci-robot · 2018-03-01T02:42:53Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: gaocegege, jlewi

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~~ [gaocegege,jlewi]

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

gaocegege · 2018-03-01T02:45:17Z

/retest

I am not sure why travis ci forgot to test the PR, maybe it is tired.

Interesting....

gaocegege · 2018-03-01T02:52:27Z

@ankushagarwal

Sorry, the CI failed because we use "github.com/sirupsen/logrus" but the vendor's logrus is "github.com/onrik/logrus"

Could you fix it?

ankushagarwal · 2018-03-01T02:55:07Z

@gaocegege : Can you link me to the failure?

We use both sirupsen/logrus and onrik/logrus

gaocegege · 2018-03-01T02:58:03Z

@ankushagarwal

Sure

http://testing-argo.kubeflow.io/timeline/kubeflow-test-infra/kubeflow-tf-operator-presubmit-tfjob-e2e-416-c2e0055-119-b903;tab=workflow;node=kubeflow-tf-operator-presubmit-tfjob-e2e-416-c2e0055-119-b903-4276748402:logs

ankushagarwal · 2018-03-01T03:25:51Z

Added sirupsen/logrus as a glide dependency - hopefully build should pass now

ankushagarwal · 2018-03-01T03:26:00Z

/retest

* Move from glog to sirupsen/logrus for logging * Add a new flag json_log_format * Refactor all log statements to use logrus * Use Info level for log level V(1) and below * Use Debug level for log level V(2) and above * Tested locally Addresses kubeflow#24 Sample logs ``` {"filename":"app/server.go:54","level":"info","msg":"EnvKubeflowNamespace not set, use default namespace","time":"2018-02-27T18:25:18-08:00"} {"filename":"app/server.go:59","level":"info","msg":"[Version: 0.3.0+git Git SHA: Not provided. Go Version: go1.9.3 Go OS/Arch: darwin/amd64]","time":"2018-02-27T18:25:18-08:00"} {"filename":"app/server.go:145","level":"info","msg":"No controller_config_file provided; using empty config.","time":"2018-02-27T18:25:18-08:00"} {"filename":"controller/controller.go:110","level":"info","msg":"Setting up event handlers","time":"2018-02-27T18:25:18-08:00"} ```

k8s-ci-robot added the size/XL label Feb 27, 2018

k8s-ci-robot assigned gaocegege and jlewi Feb 28, 2018

ankushagarwal mentioned this pull request Feb 28, 2018

Add appropriate logging fields to the tf-operator log messages #424

Closed

Use logrus for structured logging

dba7fc1

* Move from glog to sirupsen/logrus for logging * Add a new flag json_log_format * Refactor all log statements to use logrus * Use Info level for log level V(1) and below * Use Debug level for log level V(2) and above Addresses #24

k8s-ci-robot added lgtm do-not-merge/hold approved labels Feb 28, 2018

Merge remote-tracking branch 'upstream/master' into logrus

2cb25cb

gaocegege reviewed Mar 1, 2018

View reviewed changes

Move printing version to the top

c2e0055

Add sirupsen/logrus as a glide dependency

e5f5fa6

gaocegege mentioned this pull request Mar 1, 2018

Structured Logging For the operator #24

Closed

k8s-ci-robot added size/XXL and removed size/XL labels Mar 1, 2018

gaocegege approved these changes Mar 1, 2018

View reviewed changes

gaocegege merged commit 5d0d126 into kubeflow:master Mar 1, 2018

ankushagarwal deleted the logrus branch March 1, 2018 05:07

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use logrus for structured logging #416

Use logrus for structured logging #416

ankushagarwal commented Feb 27, 2018 •

edited

Loading

jlewi commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

gaocegege commented Feb 28, 2018 •

edited

Loading

gaocegege commented Feb 28, 2018

jlewi commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

gaocegege commented Mar 1, 2018

gaocegege left a comment

gaocegege commented Mar 1, 2018 •

edited

Loading

ankushagarwal commented Mar 1, 2018

gaocegege commented Mar 1, 2018

k8s-ci-robot commented Mar 1, 2018

gaocegege commented Mar 1, 2018 •

edited

Loading

gaocegege commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

gaocegege commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

Use logrus for structured logging #416

Use logrus for structured logging #416

Conversation

ankushagarwal commented Feb 27, 2018 • edited Loading

jlewi commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

gaocegege commented Feb 28, 2018 • edited Loading

gaocegege commented Feb 28, 2018

jlewi commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

jlewi commented Feb 28, 2018

ankushagarwal commented Feb 28, 2018

gaocegege commented Mar 1, 2018

gaocegege left a comment

Choose a reason for hiding this comment

gaocegege commented Mar 1, 2018 • edited Loading

ankushagarwal commented Mar 1, 2018

gaocegege commented Mar 1, 2018

k8s-ci-robot commented Mar 1, 2018

gaocegege commented Mar 1, 2018 • edited Loading

gaocegege commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

gaocegege commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

ankushagarwal commented Mar 1, 2018

ankushagarwal commented Feb 27, 2018 •

edited

Loading

gaocegege commented Feb 28, 2018 •

edited

Loading

gaocegege commented Mar 1, 2018 •

edited

Loading

gaocegege commented Mar 1, 2018 •

edited

Loading