Potential switch to/add glog logging

[mrice32]

It would be nice if we could discuss envoy logging utilities. What are the reasons for choosing spdlog over other external open source loggers, like glog? We are interested in using glog because it provides some valuable metadata, like line numbers and filenames. We could potentially add glog via the sort of generalization of logging implementation that was suggested in issue #967 or make it the standard logger for envoy if that is preferred.

As a side note, logging format doesn't appear to be mentioned under the breaking change policy. Should it be?

cc @jamessynge

[jamessynge]

I'd be interested in hearing from other users whether they depend on the existing log formats (e.g. have tools that parse them, dash boards that consume them).

@rshriram @RomanDzhabarov @mattklein123 How does this strike you?

[RomanDzhabarov]

We really rarely depend on the logs produced by the spdlog. Observability relies on stats, access logging and tracing, and I doubt there is any automation to parse those logs.

[htuch]

I think logging is a breaking change per the policy, it's user-visible since we document we use spdlog for the log format. It's helpful to know that this has no impact to Lyft.

I think we should probably open this up during business hours on Gitter for discussion. In addition to the folks @jamessynge mentions, there are a number of other users I'd like to check with that are active, including @mattwoodyard, @moderation, @kflynn, @timperrett, etc.

We probably should wait for @mattklein123 to return before making the call here, but it makes sense to start gathering input to this proposal.

[timperrett]

@htuch thanks for the consideration. Currently we're not specifically processing envoys logging format, so no objections from our end :-)

[rshriram]

If this is for debugging, then I support this effort fully. It would be nice to have glog.v(level) throughout the code so that when we debug Envoy we can turn on appropriate level of logging. Right now, it's sort of all or nothing debug logging with Envoy. And it's making it pretty difficult for us to debug envoy issues. cc @kyessenov

On Tue, May 23, 2017 at 4:40 PM Roman Dzhabarov ***@***.***> wrote: We really rarely depend on the logs produced by the spdlog. Observability relies on stats, access logging and tracing, but I doubt there is any automation to parse those logs. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1011 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AH0qd1JpYgOG_TkFNPY6s-0B8sHQZDibks5r82BWgaJpZM4NkMz0> .

-- ~shriram

[rshriram]

While doing this, would it be possible to send these logs to syslog ? Polluting stderr doesn't help much.

On Wed, May 24, 2017 at 12:15 AM htuch ***@***.***> wrote: I think logging is a breaking change per the policy, it's user-visible since we document we use spdlog for the log format. It's helpful to know that this has no impact to Lyft. I think we should probably open this up during business hours on Gitter for discussion. In addition to the folks @jamessynge <https://github.com/jamessynge> mentions, there are a number of other users I'd like to check with that are active, including @mattwoodyard <https://github.com/mattwoodyard>, @moderation <https://github.com/moderation>, @kflynn <https://github.com/kflynn>, @timperrett <https://github.com/timperrett>, etc. We probably should wait for @mattklein123 <https://github.com/mattklein123> to return before making the call here, but it makes sense to start gathering input to this proposal. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1011 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AH0qd2j3DYt7FPF9QbF_U7F8IkmrqopSks5r87pbgaJpZM4NkMz0> .

-- ~shriram

[timperrett]

@rshriram you mean optionally send to syslog right? Syslog wouldn't work for folks running envoy with containers - stdout is preferable there IMHO. With that being said its already a bit wierd with some logging to files on disk and having to sweep those files up.

[rshriram]

Oh yes optionally log to syslog. The point is that we need a way to control the firehose of logs that Envoy spews if we turn debugging on. Different logging levels 1 through N.

On Wed, May 24, 2017 at 12:31 AM Timothy Perrett ***@***.***> wrote: @rshriram <https://github.com/rshriram> you mean optionally send to syslog right? Syslog wouldn't work for folks running envoy with containers - stdout is preferable there IMHO. With that being said its already a bit wierd with some logging to files on disk and having to sweep those files up. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1011 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AH0qd1EKRl2EayEcuoCA4ptBBF4pFG2hks5r887NgaJpZM4NkMz0> .

-- ~shriram

[mattwoodyard]

While we're not parsing (or planning to parse) the built in logs, being able to easily add a custom log facility in a filter is important. Our internal filters(authn, atuhz related) add a facility that we redirect to a file.

I'm kind of -0.5 for switching to glog(performance related). It's mostly personal preference though. Spdlog has a couple of nice knobs and switches envoy isn't using/exposing. I have some internal plans to do work with logging, but either glog or spdlog can handle it. I would be sad if the ability to change per facility log levels at runtime was removed.

[mrice32]

It would be difficult to do a per-facility log levels managed by glog as far as I'm aware, but glog would allow per-file log levels that could be modified at runtime. There are also ways to log to a particular sink given a reference to the sink, which we might be able to configure to work similarly to the multiple instances of spd::logger that exist now.

[jamessynge]

@rshriram Regarding not sending to STDERR, glog will definitely support that. In normal use, I rarely see anything written to stderr or stdout from a server using glog, and instead logs go 3 files by severity of the message: ERROR, WARNING and INFO, with each log file including the messages from the more serious levels above it. And there is a FATAL log if the program crashes. You can choose to send the output to STDERR for debugging purposes.

Regarding verbose logging (beyond INFO), glog includes the macros VLOG(level) and DVLOG(level), where the runtime level defaults to zero, so these macros normally don't emit any output, but if the level is raised then they will (to the INFO log only, IIRC). DVLOG is compiled out in opt builds, so that you can include a bunch of such statements if necessary, and they won't impact performance in production builds. And as @mrice32 indicated, there is a runtime verbosity level that is global to the whole program, but which can be overridden at the per-file level (based on FILE at compile time).

[mrice32]

Is anyone actively using the API calls to modify log levels at runtime?

[mattwoodyard]

We use it occasionally for debugging, as our deployment has matured I find myself using it less and less.

…

On May 24, 2017 1:04 AM, "htuch" ***@***.***> wrote: I think logging is a breaking change per the policy, it's user-visible since we document we use spdlog for the log format. It's helpful to know that this has no impact to Lyft. I think we should probably open this up during business hours on Gitter for discussion. In addition to the folks @jamessynge <https://github.com/jamessynge> mentions, there are a number of other users I'd like to check with that are active, including @mattwoodyard <https://github.com/mattwoodyard>, @moderation <https://github.com/moderation>, @kflynn <https://github.com/kflynn>, @timperrett <https://github.com/timperrett>, etc. We probably should wait for @mattklein123 <https://github.com/mattklein123> to return before making the call here, but it makes sense to start gathering input to this proposal. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1011 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAblddp4X5B2mVezi9REKN1404aBQowHks5r87pbgaJpZM4NkMz0> .

[mattklein123]

I'm not in favor of this proposal. spdlog was chosen because I've used many logging frameworks, and I like the design/performance of spdlog. It's very flexible and I like that it's built on top of the fmt library.

Swapping out spdlog for glog will yield a tremendous amount of code churn for dubious benefit. I would much rather have a discussion about what the complaints are regarding the current logging situation, and then see if we can do targeted fixes to the current logger before talking about a full swap out. So, let's start there. What are the complaints? So far I've heard:

• from @rshriram "Right now, it's sort of all or nothing debug logging with Envoy". This isn't true. Envoy supports multiple log levels and multiple facilities, so not sure what this means.

• from @mrice32 "We are interested in using glog because it provides some valuable metadata, like line numbers and filenames". Obviously, this is only possible because all log statements are macros. As it happens, the majority of log statements in Envoy are also already macros, so adding file/line would be trivial, and that could be extended to the others easily.

In general, spdlog supports custom formatters, so any (or many) output formats could be easily generated if we want.

Happy to discuss in a meeting also, but mainly want to make sure that we are getting good value out of the very large amount of work and code churn this proposal is going to entail.

[htuch]

@mattklein123 Another argument that comes up from folks (including myself) is that glog makes debugging a lot easier and adding log statements lightweight. Adding a new log statement is a one line change, without having to muck with class structure and inheritance, which doesn't play well when trying to instrument a static utility function.

The argument might be made that we should just use cerr etc. during debug. I think this is problematic, since you then lose the trail of breadcrumbs you lay down during debugging which might be useful to upstream for future insight.

That said, if we can come up with a sensible way to use spdlog using macros (e.g. with some wrapper class) then this is less of an issue.

[mattklein123]

The argument might be made that we should just use cerr etc. during debug. I think this is problematic

TBH, IMO I think too much logging is just as bad as too little logging. Having to think about which logs to keep is important, and I think a little friction is not terrible. Using std::cerr for temp debugging is a good indication to remove stuff when done.

With that said, I think friction for single line debugging is a reasonable complaint. What if we had macros for quick debugging that pull a default facility out of the registry, and log to it, including file name and line? This is trivial to add. We could also add file name and line to the other existing macros?

I'm not trying to be difficult here, I'm just trying to figure out if we can make people happy without mega churn.

[mattklein123]

OK I think we closed on this and we aren't doing it. We can reopen if we decide to do it later.