Switch to Istio logging #2240

nmittler · 2017-12-19T00:27:45Z

This completes the transition from the entire Istio code base over
to the new Istio logging library (replacing glog).

The mapping is roughly as follows:

glog.Debug -> log.Debug
glog.Info -> log.Info
glog.Warning -> log.Warn
glog.Error -> log.Error
glog.Fatal -> log.Error + os.Exit(-1)
glog.V(1) -> log.Info
glog.V(2) -> log.Info
glog.V(3+) -> log.Debug
glog.Flush -> log.Sync

Partially addresses #2174

None

nmittler · 2017-12-19T00:29:05Z

pilot/proxy/envoy/watcher.go

 		args = append(args, "-l", "trace")
-	} else if glog.V(3) {
+	} /* TODO(nmittler): When should the "debug" flab be used?


@kyessenov any thoughts on how to handle this?

This will require a new flag.

@kyessenov I've created #2257 to address this.

codecov · 2017-12-19T00:32:17Z

Codecov Report

Merging #2240 into master will decrease coverage by 0.17%.
The diff coverage is 51.53%.

@@            Coverage Diff             @@
##           master    #2240      +/-   ##
==========================================
- Coverage   76.42%   76.24%   -0.18%     
==========================================
  Files         221       69     -152     
  Lines       19810     5886   -13924     
==========================================
- Hits        15139     4488   -10651     
+ Misses       3846     1155    -2691     
+ Partials      825      243     -582

Flag	Coverage Δ
#broker	`47.27% <50%> (-28.1%)`	⬇️
#mixer	`?`
#pilot	`76.95% <46.56%> (-1.47%)`	⬇️
#security	`87.08% <79.16%> (+10.89%)`	⬆️

Impacted Files	Coverage Δ
broker/pkg/version/version.go	`100% <ø> (ø)`	⬆️
pilot/platform/cloudfoundry/config.go	`94.73% <ø> (ø)`	⬆️
broker/pkg/model/osb/catalog.go	`100% <ø> (ø)`	⬆️
pilot/platform/eureka/controller.go	`90.62% <0%> (ø)`	⬆️
pilot/platform/kube/client.go	`40.9% <0%> (ø)`	⬆️
pilot/cmd/pilot-discovery/server/monitoring.go	`64% <0%> (ø)`	⬆️
pilot/platform/consul/monitor.go	`80.88% <0%> (+69.11%)`	⬆️
pilot/platform/cloudfoundry/controller.go	`64.28% <0%> (ø)`	⬆️
pilot/platform/kube/register.go	`43.13% <0%> (+0.41%)`	⬆️
pilot/proxy/resolve.go	`0% <0%> (ø)`	⬆️
... and 170 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 87aa56e...599b50d. Read the comment docs.

ldemailly · 2017-12-19T00:32:19Z

glog.V(1) -> log.Warn

That seems wrong, any Vlog should be Info or lower (verbose means verbose not warning)

Maybe this shows another level (Verbose) should be added ?

kyessenov · 2017-12-19T00:34:35Z

glov.V(1) is not warn! It's all verbose. But we should not print every verbose log message, since there are tons per-request ones.

nmittler · 2017-12-19T00:35:31Z

@ldemailly @kyessenov I've corrected the V(1) mapping in the description ... it was already Info in the code.

kyessenov

Please re-direct client-go log output to istio log. Without a single log output, we have a strict degradation in debuggability of Pilot. I want to be able to get a sequential trace across the stack, not two separate log streams.

nmittler · 2017-12-19T00:38:05Z

Please re-direct client-go log output to istio log. Without a single log output, we have a strict degradation in debuggability of Pilot. I want to be able to get a sequential trace across the stack, not two separate log streams.

@kyessenov is that what glog was doing previously? If not, it would seem to be beyond the scope of this PR.

kyessenov · 2017-12-19T00:41:18Z

If you try to debug k8s, there's a major difference between different log levels. Level 10 is per-request, typically. Can we preserve that in istio log? We have way too much logging already, and we're losing all the tuning we've done before.

nmittler · 2017-12-19T00:42:35Z

If you try to debug k8s, there's a major difference between different log levels. Level 10 is per-request, typically. Can we preserve that in istio log? We have way too much logging already, and we're losing all the tuning we've done before.

@kyessenov so what do you propose as the mapping?

kyessenov · 2017-12-19T00:44:33Z

Not sure, maybe @geeknoid has some ideas?..

nmittler · 2017-12-19T00:47:21Z

@kyessenov @geeknoid IIRC, Martin's changes to Mixer mapped all V(x) logs to Debug. Would that address your concerns?

nmittler · 2017-12-19T16:20:40Z

@geeknoid any thoughts on #2240 (comment)?

nmittler · 2017-12-19T16:22:59Z

Please re-direct client-go log output to istio log.

@kyessenov can you provide me more detail on what would need to be done here?

nmittler · 2017-12-19T17:07:41Z

@geeknoid I'm seeing that the pilot-integration-x tests are failing with Too long with no output. Do we need to redirect logs to stdout or something?

nmittler · 2017-12-19T18:33:33Z

/retest

ldemailly · 2017-12-19T19:29:43Z

@geeknoid what do you think about adding a level in between Debug and Info : Verbose ?

geeknoid · 2017-12-19T21:34:08Z

@ldemailly We have limited flexibility in introducing new levels since our logging package is a layer on top of the Zap logger, which is where the levels are defined. What we have:

Error, Warning, Info: on all the time
Debug: all the extra stuff that must be explicitly turned on

If there's some Info-level things that we want to be conditionally enabled, you need to have a separate command-line option to control that specifically.

nmittler · 2017-12-20T20:09:42Z

pilot/cmd/cmd.go

-// AddFlags carries over glog flags with new defaults
-func AddFlags(rootCmd *cobra.Command) {
+// InitRootCommand Initializes the root command with logging configuration
+func InitRootCommand(rootCmd *cobra.Command, loggingOptions *log.Options) {


@kyessenov please review the changes here for configuring istio logging and glogs

nmittler · 2017-12-20T20:10:11Z

tests/e2e/framework/framework.go

 // Should be called right after flag.Parse().
-func InitGlog() error {
+func InitLogging() error {


@kyessenov Also please review here

I'm not sure this should be done. @geeknoid?

So a couple things:

At the moment, Mixer does none of that. Output go to stdout unless the user redirects it to a specific file.

Uses of glog in Mixer need to be configured independently using glog options.

I'm playing right now with providing a replacement for glog which calls into the zap library directly. This would eliminate all classic glog command-line options and features from our builds.

I'm expecting to extend our logging package to support log rotation explicitly. It's fairly easy to do on top of zap. Adding this functionality will involve introducing new cmd-line flags to allow the user to select a target directory, max file size, num files to keep, etc.

So given all the above, I would probably just go with a simple story for the time being, like Mixer has. The smarts will then be introduced by silent upgrades to the log package.

@geeknoid sgtm. I've updated the PR to remove some of the glog-specific gunk.

kyessenov · 2017-12-20T20:15:07Z

Looks mostly OK from what I scanned over in pilot. Seems like you made V<=2 Info and V > 2 Debug. That means we get too much Info levels and too much for Debug levels, but that should not be blocking this PR.

I'd prefer if we had a discussion before undertaking the entire log swapping business. I don't see it as valuable since it makes it hard to separate code out of istio repository.

This completes the transition from the entire Istio code base over to the new Istio logging library (replacing glog). The mapping is roughly as follows: glog.Debug -> log.Debug glog.Info -> log.Info glog.Warning -> log.Warn glog.Error -> log.Error glog.Fatal -> log.Error + os.Exit(-1) glog.V(1) -> log.Info glog.V(2) -> log.Info glog.V(3+) -> log.Debug glog.Flush -> log.Sync Partially addresses istio#2174

nmittler · 2018-01-02T18:39:31Z

@costinm I found and fixed the problem

nmittler · 2018-01-02T18:43:58Z

@kyessenov mind re-lgtm/approving?

ZackButcher · 2018-01-02T18:53:31Z

/lgtm
/approve

istio-merge-robot · 2018-01-02T18:54:14Z

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

kyessenov · 2018-01-02T19:05:09Z

/lgtm
/approve

istio-merge-robot · 2018-01-02T19:05:56Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: kyessenov, ZackButcher

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

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

~~broker/OWNERS~~ [kyessenov]
~~mixer/OWNERS~~ [ZackButcher,kyessenov]
~~pilot/OWNERS~~ [ZackButcher,kyessenov]
~~security/OWNERS~~ [kyessenov]
~~tests/OWNERS~~ [kyessenov]

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

istio-merge-robot · 2018-01-02T19:28:17Z

Automatic merge from submit-queue.

ldemailly · 2018-01-02T19:31:31Z

glog.V(2) -> log.Info

that seems like way too many logs by default
also V(x) has short circuit logic / is often bracketted in if (glog.V(2) { ... calculate expensive debug... } what's the "istio logger" way of doing that ?

ZackButcher · 2018-01-02T19:41:20Z

@ldemailly log.InfoEnabled() bool et al.

ldemailly · 2018-01-02T19:49:45Z

So are we going to run prod with warnings only ? as I mentioned earlier there are rare info messages one wants to always see in the logs without artificially labelling them as warning

ZackButcher · 2018-01-02T19:54:57Z

IIRC, by default we log Error, Warning, and Info. I believe Pilot was originally running with -v 2 anyway, so this shouldn't result in more logging than today:

istio/install/kubernetes/templates/istio-pilot.yaml.tmpl

Lines 115 to 116 in 55d591f

ldemailly · 2018-01-02T21:10:27Z

for perf test I remove -v 2 so I get Info... what should I do now ?

mattdelco

Parts of the build (at least bazel_to_go) seem unhappy with the comments added to some of the BUILD files. E.g.

Step #1: ERROR: /workspace/go/src/istio.io/istio/broker/pkg/model/osb/BUILD:17:9: syntax error at '//': expected expression.

mattdelco · 2018-01-02T21:08:47Z

broker/pkg/model/osb/BUILD

@@ -12,6 +12,9 @@ go_library(
        "servicePlan.go",
    ],
    deps = [
+        "//pkg/log:go_default_library",
+
+        // TODO(nmittler): Remove this


Should be # not //

mattdelco · 2018-01-02T21:09:22Z

broker/pkg/version/BUILD

+    deps = [
+        "//pkg/log:go_default_library",
+
+        // TODO(nmittler): Remove this


Should be # not //

nmittler · 2018-01-02T23:03:19Z

@mattdelco Just filed #2373 to fix

Automatic merge from submit-queue. Fix BUILD files

ldemailly · 2018-01-03T05:39:42Z

@ZackButcher for perf test I remove -v 2 so I get Info logging (pre 'new logger')... what should I do now ?

ZackButcher · 2018-01-03T16:43:57Z

Use the flags in the new log package:

istio/pkg/log/options.go

Lines 188 to 189 in 337c240

    
           cmd.PersistentFlags().StringVar(&o.outputLevel, "log_output_level", o.outputLevel, 
        
           	"The minimum logging level of messages to output, can be one of debug, info, warning, error, or none")

Off topic of this PR: we really need to standardize our flag format; this mix of flag-name and flag_name sucks; personally I'm a much bigger fan of flag-name /cc @geeknoid

ldemailly · 2018-01-03T16:51:38Z

so you are suggesting people run prod with warning, that seems wrong as some low volume info level are useful, we don’t have the right levels

ZackButcher · 2018-01-03T17:05:24Z

No, our intent is that you can run at info in prod (and this is the default behavior). We likely need to rework some of our logging to make that a reality.

ldemailly · 2018-01-03T19:15:34Z

Just to be clear it's a regression from 0.4.0 where running -v 0 would give you some amount of Info separated from verbose per request logging and we lost this now by merging v1,v2 and info into a single bucket

ldemailly · 2018-01-03T19:22:33Z

let's move the levels discussion to #2400

nmittler requested review from ZackButcher and geeknoid December 19, 2017 00:27

istio-testing added the release-note-none label Dec 19, 2017

googlebot added the cla: yes label Dec 19, 2017

nmittler commented Dec 19, 2017

View reviewed changes

kyessenov requested changes Dec 19, 2017

View reviewed changes

nmittler force-pushed the logging branch from 26a51aa to 2649faf Compare December 19, 2017 16:18

geeknoid removed their request for review December 19, 2017 18:25

nmittler added the pilot label Dec 19, 2017

nmittler force-pushed the logging branch 2 times, most recently from 18bb461 to 256ade5 Compare December 19, 2017 21:08

nmittler commented Dec 20, 2017

View reviewed changes

kyessenov approved these changes Dec 20, 2017

View reviewed changes

nmittler force-pushed the logging branch from 7a9e890 to 599b50d Compare January 2, 2018 18:04

istio-testing assigned ZackButcher Jan 2, 2018

istio-testing added the lgtm label Jan 2, 2018

istio-merge-robot merged commit b25c2e9 into istio:master Jan 2, 2018

mattdelco reviewed Jan 2, 2018

View reviewed changes

nmittler added a commit to nmittler/istio that referenced this pull request Jan 2, 2018

Fix BUILD files broken by istio#2240

b72d044

nmittler mentioned this pull request Jan 2, 2018

Fix BUILD files #2373

Merged

istio-merge-robot pushed a commit that referenced this pull request Jan 3, 2018

Fix BUILD files broken by #2240 (#2373)

d80c855

Automatic merge from submit-queue. Fix BUILD files

ldemailly mentioned this pull request Jan 3, 2018

istio logging level missing a level between info and debug or need to move a lot of logging to debug - logger #2400

Closed

ozevren mentioned this pull request Aug 13, 2018

Seeing logs of certificate modified events #7872

Closed

Switch to Istio logging #2240

Switch to Istio logging #2240

Uh oh!

Conversation

nmittler commented Dec 19, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov bot commented Dec 19, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

ldemailly commented Dec 19, 2017

Uh oh!

kyessenov commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

kyessenov left a comment

Choose a reason for hiding this comment

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

kyessenov commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

kyessenov commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

nmittler commented Dec 19, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nmittler commented Dec 19, 2017

Uh oh!

ldemailly commented Dec 19, 2017

Uh oh!

geeknoid commented Dec 19, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kyessenov commented Dec 20, 2017

Uh oh!

nmittler commented Jan 2, 2018

Uh oh!

nmittler commented Jan 2, 2018

Uh oh!

ZackButcher commented Jan 2, 2018

Uh oh!

istio-merge-robot commented Jan 2, 2018

Uh oh!

kyessenov commented Jan 2, 2018

Uh oh!

istio-merge-robot commented Jan 2, 2018

Uh oh!

istio-merge-robot commented Jan 2, 2018

Uh oh!

ldemailly commented Jan 2, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ZackButcher commented Jan 2, 2018

Uh oh!

nmittler commented Dec 19, 2017 •

edited

Loading

codecov bot commented Dec 19, 2017 •

edited

Loading

nmittler commented Dec 19, 2017 •

edited

Loading

ldemailly commented Jan 2, 2018 •

edited

Loading

ldemailly commented Jan 2, 2018 •

edited

Loading

ZackButcher commented Jan 2, 2018 •

edited

Loading

ZackButcher commented Jan 3, 2018 •

edited

Loading