Improve logging usage #496

mz-pdm · 2017-10-06T07:27:17Z

No description provided.

kubevirt-bot · 2017-10-06T07:29:06Z

Can one of the admins verify this patch?

petrkotas · 2017-10-06T14:36:39Z

I will copy the commit message from first commit here, it describes the goals of this commit and it got lost by github.

Improve logging usage

The structured logger is good for producing comprehensive logs, however it is
not that good for being used directly in the code. Let's introduce some
changes that:

Make the code shorter, so it's easier to read.
Make the logging lines shorter, so the logging messages can be read without
horizontal scrolling.
Reduce the chain of method calls so one can see easily also code other than
logging in editors highlighting method calls.
Reduce code duplication.

To not make logging too messy, methods for setting message levels are turned
into terminal methods. Those methods are almost always used, so they can be
used as such rather than using extra Msg method call. In rare cases when we
don't want to use typical logging patterns, new Level method can be used.

It would be nice to access logging methods from objects being logged.
However due to Go limitations we can't do that easily, so we have to use
something like vm.Log().Info' rather than simply vm.Info'.

petrkotas · 2017-10-06T14:39:51Z

I like this patch. The logging is now more readable and shorter to write.

davidvossel · 2017-10-09T15:10:22Z

retest this please

davidvossel

Overall this looks fine to me. In the future, if we start using filtered loggers other than the DefaultLogger, we might want to re-evaluate some of the helper functions that abstract away that the DefaultLogger is being used, but for now I don't see any problems with the helper functions.

The only thing that caught my eye was the VM object's log function. I'm not sure that's a pattern we want to start using. I'd be okay with still having to specify Object() to avoid adding Log() functions for each cluster object we work with.

davidvossel · 2017-10-09T15:22:45Z

pkg/logging/logging_test.go

@@ -297,8 +323,8 @@ func TestObject(t *testing.T) {
 	setUp()
 	log := MakeLogger(MockLogger{})
 	log.SetLogLevel(DEBUG)
-	vm := v1.VirtualMachine{}
-	log.Object(&vm).Log("test", "message")
+	vm := newVM()


why change this?

mz-pdm · 2017-10-09T16:45:55Z

David Vossel <notifications@github.com> writes:

The only thing that caught my eye was the VM object's log function. I'm not sure that's a pattern we want to start using. I'd be okay with still having to specify Object() to avoid adding Log() functions for each cluster object we work with.

It's not necessary to add Log() to each cluster object, just to those that are worth it (i.e. define once, use many times) – the rest can use Object(). I don't know whether there are already some ideas about using different loggers, but if we like to use separate loggers for some objects then object Log() functions will help with that. And Log() implementation is trivial, so it's not a big deal. Despite that I'm not particularly happy with it too, it lacks some elegance. But it's IMO still better to use o.Log() than let's say logging.Object(o), for the reasons mentioned in the commit message. Maybe somebody has a better idea?

-------------------------------------------------------------------------------------------------------------------- In pkg/logging/logging_test.go: > @@ -297,8 +323,8 @@ func TestObject(t *testing.T) { setUp() log := MakeLogger(MockLogger{}) log.SetLogLevel(DEBUG) - vm := v1.VirtualMachine{} - log.Object(&vm).Log("test", "message") + vm := newVM() why change this?

To avoid circular package references.

davidvossel · 2017-10-09T17:48:14Z

Despite that I'm not particularly happy with it too, it lacks some
elegance. But it's IMO still better to use o.Log() than let's say
logging.Object(o), for the reasons mentioned in the commit message.

I agree that it o.Log() looks nicer than logging.Object(o). I don't feel good about making our logging package a dependency for things like /pkg/api/v1 now though. That's what we have to do in order to get this functionality. It's also why you had to work around the circular dependency.

rmohr · 2017-10-10T07:18:11Z

I can understand the desire to make the logging lines a little bit shorter, however, I am also not very happy with the changes here.

We are using a structured logger, and I like that with the builder we have clearly structured way on what logs what. E.g. the .Object(vm), logs object information. If we later on also want to log the controller, we can simply do something like .Controller(migration).Object(vm), or .Object(vm).ManagedBy(migration). I also explicitly like the separation of .Reason() and .Msg(), because it also corresponds to what will be logged in which fields.

Some thoughts on how to make the lines a little bit shorter:

Having a the logging.DefaultLogger() is very long. Renaming logging to e.g. log and have a global Log variable which is set to logging. DefaultLogger().
Since V() only makes sense in combination with Info(), let's combine it

The outcome would be:

log.Log.Info().With("costm_key", "custom_val" ).Msg("whatever") # defaults to InfoV(1)
log.Log.InfoV(3).With("costm_key", "custom_val" ).Msg("whatever")
log.Log.Error().Reason(err).Msg("lala") # reason is not a must, but msg is.

It can be made even shorter by having a log.Error(), log.Info(), ... global method for the default logger in the log package.

If it is confusing for people, that .Msg() or .Msgf() are the the last ones executed, renaming it to .Log() or .Logf() would also be an option for me.

mpolednik · 2017-10-10T07:40:15Z

Since V() only makes sense in combination with Info(), let's combine it

Please let's keep at least some consistency in the Go universe and keep V() a function.

As for the logging itself, if we really want structured logging (which I'm not fan of, not with the code burden that glog doesn't carry) AND a bit of consistency with kube*, I could imagine getting rid of message and making Info, Error, Warning etc. terminals in the builder. That would lead to logging lines such as

logging.DefaultLogger().Object(VM).Reason(Err).Error("VM isn't running")

The advantage of that is if you remove the structured part, you'll arrive to a point where the line looks similarly to other logging frameworks:

logging.DefaultLogger. ... .Error("VM isn't running")
---------------------/
imagine this being *log

rmohr · 2017-10-10T07:49:48Z

logging.DefaultLogger().Object(VM).Reason(Err).Error("VM isn't running")

+1

As for the logging itself, if we really want structured logging (which I'm not fan of, not with the code burden that glog doesn't carry)

I really want to use structured logging.

mz-pdm · 2017-10-10T07:54:06Z

David Vossel <notifications@github.com> writes:

I agree that it o.Log() looks nicer than logging.Object(o). I don't feel good about making our logging package a dependency for things like /pkg/api/v1 now though. That's what we have to do in order to get this functionality.

OK, I can omit that in the patch and we can look for better ways to express it in future patches (again: suggestions welcome).

mz-pdm · 2017-10-10T08:52:36Z

Roman Mohr <notifications@github.com> writes:

We are using a structured logger, and I like that with the builder we have clearly structured way on what logs what. E.g. the .Object(vm), logs object information. If we later on also want to log the controller, we can simply do something like .Controller(migration).Object(vm), or .Object(vm).ManagedBy(migration). I also explicitly like the separation of .Reason() and .Msg(), because it also corresponds to what will be logged in which fields.

Such an approach makes logging calls the most complex lines in the source code. This is the reason why I made this pull request, I've found some source files hard to read due to logging (see the commit message for details).

Some thoughts on how to make the lines a little bit shorter:

Typically the best way is to extract common repetitive patterns. This is for instance the idea behind having reason as an Error() argument, since it is typically provided and if it is not then one should explicitly use `nil' to say “there's no special reason behind this error”.

* Having a the logging.DefaultLogger() is very long. Renaming logging to e.g. log and have a global Log variable which is set to logging. DefaultLogger(). * Since V() only makes sense in combination with Info(), let's combine it

If V() is typically used with Info() then why not (yes, I disagree here with Martin).

The outcome would be: log.Log.Info().With("costm_key", "custom_val" ).Msg("whatever") # defaults to InfoV(1) log.Log.InfoV(3).With("costm_key", "custom_val" ).Msg("whatever") log.Log.Error().Reason(err).Msg("lala") # reason is not a must, but msg is. It can be made even shorter by having a log.Error(), log.Info(), ... global method for the default logger in the log package.

Yes, looks like a good idea.

If it is confusing for people, that .Msg() or .Msgf() are the the last ones executed, renaming it to .Log() or .Logf() would also be an option for me.

[...]

logging.DefaultLogger().Object(VM).Reason(Err).Error("VM isn't running") +1

OK. So the minimum common base we could agree on now seems to be: - Changing logging.DefaultLogger() to log.Log. - Making Info(), Error(), etc. terminals. - Nobody has protested against using additional arguments for formatted strings so I can think I can keep that too. So we can start with that and we'll see later. I think I can in any case make an Emacs mode for common pattern transformations although one shouldn't need IDE to read KubeVirt sources :-).

rmohr · 2017-10-10T09:07:37Z

Changing logging.DefaultLogger() to log.Log.

Works for me

Making Info(), Error(), etc. terminals.

Works for me

Nobody has protested against using additional arguments for formatted
strings so I can think I can keep that too.

I would suggest Error() and Errorf() if that is what you mean.

mz-pdm · 2017-10-12T16:19:04Z

I believe I made all the agreed changes in the updated version of the patch.

davidvossel

works for me 👍

rmohr

I think we need a rebase, but looks good otherwise.

davidvossel · 2017-10-16T17:48:30Z

It sounds like we're in agreement this should go in.

Since this touches so many files, we should merge this immediately once it is rebased.

The structured logger is good for producing comprehensive logs, however it is not that good for being used directly in the code. Let's introduce some changes that: - Make the code shorter, so it's easier to read. - Make the logging lines shorter, so the logging messages can be read without horizontal scrolling. - Reduce the chain of method calls so one can see easily also code other than logging in editors highlighting method calls. - Reduce code duplication. To not make logging too messy, methods for setting message levels are turned into terminal methods (and their formatting argument variants are introduced). Those methods are almost always used, so they can be used as such rather than using extra Msg method call. In rare cases when we don't want to use typical logging patterns, new Level method can be used. `logging' package is renamed to `log' and `Log' instance of DefaultLogger() is created to make log lines significantly shorter.

mz-pdm · 2017-10-23T11:20:10Z

Rebased and updated.

rmohr · 2017-10-23T11:40:59Z

ok to test

rmohr · 2017-10-23T12:03:56Z

@mz-pdm thanks!

update kubernetes libraries 1.11.2 (same as KubeVirt)

* Copy files over for 1.20 Signed-off-by: Daniel Hiller <dhiller@redhat.com> * Change from experimental-kustomize to experimental-patches kubeadm init --experimental-kustomize was deprecated in 1.20 therefore we resort to using strategic patches. Signed-off-by: Daniel Hiller <dhiller@redhat.com>

davidvossel reviewed Oct 9, 2017

View reviewed changes

mz-pdm force-pushed the logging2 branch from 72435c4 to 2a9a4a2 Compare October 12, 2017 16:15

davidvossel approved these changes Oct 16, 2017

View reviewed changes

rmohr approved these changes Oct 16, 2017

View reviewed changes

mz-pdm added 2 commits October 23, 2017 13:02

Minor typo fix in domain_test.go

e2cdbb7

mz-pdm force-pushed the logging2 branch from 2a9a4a2 to e2cdbb7 Compare October 23, 2017 11:18

rmohr approved these changes Oct 23, 2017

View reviewed changes

rmohr merged commit 8db0023 into kubevirt:master Oct 23, 2017

rmohr mentioned this pull request Oct 23, 2017

Improve the logging #415

Closed

kubevirt-bot pushed a commit to kubevirt-bot/kubevirt that referenced this pull request Nov 6, 2020

Merge pull request kubevirt#496 from mhenriks/update-kubernetes

c2ebee5

update kubernetes libraries 1.11.2 (same as KubeVirt)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logging usage #496

Improve logging usage #496

mz-pdm commented Oct 6, 2017

kubevirt-bot commented Oct 6, 2017

petrkotas commented Oct 6, 2017 •

edited

petrkotas commented Oct 6, 2017

davidvossel commented Oct 9, 2017

davidvossel left a comment

davidvossel Oct 9, 2017

mz-pdm commented Oct 9, 2017 via email

davidvossel commented Oct 9, 2017

rmohr commented Oct 10, 2017

mpolednik commented Oct 10, 2017

rmohr commented Oct 10, 2017

mz-pdm commented Oct 10, 2017 via email

mz-pdm commented Oct 10, 2017 via email

rmohr commented Oct 10, 2017

mz-pdm commented Oct 12, 2017

davidvossel left a comment

rmohr left a comment

davidvossel commented Oct 16, 2017

mz-pdm commented Oct 23, 2017

rmohr commented Oct 23, 2017

rmohr commented Oct 23, 2017

Improve logging usage #496

Improve logging usage #496

Conversation

mz-pdm commented Oct 6, 2017

kubevirt-bot commented Oct 6, 2017

petrkotas commented Oct 6, 2017 • edited

Improve logging usage

petrkotas commented Oct 6, 2017

davidvossel commented Oct 9, 2017

davidvossel left a comment

Choose a reason for hiding this comment

davidvossel Oct 9, 2017

Choose a reason for hiding this comment

mz-pdm commented Oct 9, 2017 via email

davidvossel commented Oct 9, 2017

rmohr commented Oct 10, 2017

mpolednik commented Oct 10, 2017

rmohr commented Oct 10, 2017

mz-pdm commented Oct 10, 2017 via email

mz-pdm commented Oct 10, 2017 via email

rmohr commented Oct 10, 2017

mz-pdm commented Oct 12, 2017

davidvossel left a comment

Choose a reason for hiding this comment

rmohr left a comment

Choose a reason for hiding this comment

davidvossel commented Oct 16, 2017

mz-pdm commented Oct 23, 2017

rmohr commented Oct 23, 2017

rmohr commented Oct 23, 2017

petrkotas commented Oct 6, 2017 •

edited