[DISCUSS] Change Jenkins default logging format

[Baptiste Mathus]

Hello everyone,

Having worked on more things related to Jenkins logging recently, I've had the opportunity to remember my past pain when I was operating a Jenkins instance and sending logs to an ELK cluster.

Compared to almost everything else in the infrastructure, the logstash rules for Jenkins logs were unnecessarily complex.

The main pain-points, for me at least, had been the two-lines (sigh) per log default, and also the localized date format (or log level...). 

Even now, so many years after reading those, I still struggle daily to make sure I'm reading the right line/date associated to the message I'm reading on the line above.

I would like to propose we change the current logging format behavior to a more readable and more operation-friendly one.

This would result in something close to the following format:

[   INFO][2018-04-04 12:40:49] Logging initialized @180ms to org.eclipse.jetty.util.log.JavaUtilLog (from org.eclipse.jetty.util.log.Log initialized)

[   INFO][2018-04-04 12:40:49] Beginning extraction from war file (from winstone.Logger logInternal)

[WARNING][2018-04-04 12:40:49] Empty contextPath (from org.eclipse.jetty.server.handler.ContextHandler setContextPath)

[   INFO][2018-04-04 12:40:49] jetty-9.4.z-SNAPSHOT (from org.eclipse.jetty.server.Server doStart)

Instead of the usual:

Apr 04, 2018 12:36:41 PM org.eclipse.jetty.util.log.Log initialized

INFO: Logging initialized @354ms to org.eclipse.jetty.util.log.JavaUtilLog

Apr 04, 2018 12:36:41 PM winstone.Logger logInternal

INFO: Beginning extraction from war file

Apr 04, 2018 12:36:42 PM org.eclipse.jetty.server.handler.ContextHandler setContextPath

WARNING: Empty contextPath

Apr 04, 2018 12:36:42 PM org.eclipse.jetty.server.Server doStart

INFO: jetty-9.4.z-SNAPSHOT

WDYT?

If this looks interesting to people, I'm ready to file the associated JEP for it and possibly work on its implementation in the future.

Obviously, we would need some way to revert to the "legacy" format, at least for some time for users to adapt. But that is not something I'm particularly worried about.

-- Baptiste

[Oleg Nenashev]

Hi Baptiste,

Anyone can easily change the logging format in Jenkins by passing custom J.U.L properties file.
So it should not be a problem to change logging format even if you do not add a custom logging appender for ELK.

Changing a default logging format may cause regressions in existing monitoring systems. I would rather be conservative and keep the default logging format in Jenkins unless there is a strong justification to do that. New subprojects like Jenkins Essentials and Jenkins X could easily change the default format, because they have no compatibility commitment so far.

Best regards,
Oleg

[Daniel Beck]

> On 4. Apr 2018, at 18:12, Oleg Nenashev <o.v.ne...@gmail.com> wrote:
>
> Changing a default logging format may cause regressions in existing monitoring systems. I would rather be conservative and keep the default logging format in Jenkins unless there is a strong justification to do that.

I expect that a change in logging format would surface quickly enough to not cause major headaches. Users with elaborate monitoring are probably also more likely to use LTS and we can cover this change in an upgrade guide.

The format is annoying enough that we should change it to something sane.

[R. Tyler Croy]

(replies inline)

On Wed, 04 Apr 2018, Oleg Nenashev wrote:

> Hi Baptiste,
>
> Anyone can easily change the logging format in Jenkins by passing custom
> J.U.L properties file.
> So it should not be a problem to change logging format even if you do not
> add a custom logging appender for ELK.
>
> Changing a default logging format may cause regressions in existing
> monitoring systems. I would rather be conservative and keep the default
> logging format in Jenkins unless there is a strong justification to do
> that. New subprojects like Jenkins Essentials and Jenkins X could easily
> change the default format, because they have no compatibility commitment so
> far.

Thanks for sharing your thoughts Oleg, it makes me wonder: how could we
quantify the positive/negative impact of this (arguably) "bad default."

I'm reminded of some of the pre-Jenkins 2 discussions about security defaults
for example. I spent some time trying to discover Jenkins-log-parsing projects,
tools, and their communities to which we could reach out. Unfortunately I
wasn't able to find anything big past a couple of blog posts :-/

From my personal experience as an Operator, compact and easily parseable
(sed/awk/perl) one-line logs are HUGELY valuable and worth any temporary
heartburn some people may experience with their existing hacks.



Cheers

- R. Tyler Croy

------------------------------------------------------
Code: <https://github.com/rtyler>
Chatter: <https://twitter.com/agentdero>
xmpp: rty...@jabber.org

% gpg --keyserver keys.gnupg.net --recv-key 1426C7DC3F51E16F
------------------------------------------------------

[Carlos Sanchez]

I'm +1 to change the format. 2 lines is really annoying

--
You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-dev+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/20180404172432.wlr4c5f35tuvnijj%40blackberry.coupleofllamas.com.

For more options, visit https://groups.google.com/d/optout.

[Arnaud Héritier]

I think I already claimed my hate for this logging format many times.

For sure I understand Oleg's concern with the impact of changing the default settings.

Like always for such kind of change when we don't really know how it could impact our users I would prefer to introduce the change non activated by default in 2.x and wait a 3.x for the change of the default value but if we have to wait for 500 weeklies before the 3.x ..... I'm a bit septic about my approach

To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CALHFn6NsdOsMRtD%3DacAATvOiY_Wo15gxu6Fwh5iRCs3ogqMmfQ%40mail.gmail.com.

For more options, visit https://groups.google.com/d/optout.

--

-----

Arnaud Héritier

http://aheritier.net

Mail/GTalk: aheritier AT gmail DOT com

Twitter/Skype : aheritier

[Baptiste Mathus]

2018-04-04 18:12 GMT+02:00 Oleg Nenashev <o.v.ne...@gmail.com>:

Hi Baptiste,

Anyone can easily change the logging format in Jenkins by passing custom J.U.L properties file.

Yes. But in practice, I'm convinced virtually nobody does this.

 

So it should not be a problem to change logging format even if you do not add a custom logging appender for ELK.

Changing a default logging format may cause regressions in existing monitoring systems. I would rather be conservative and keep the default logging format in Jenkins unless there is a strong justification to do that. New subprojects like Jenkins Essentials and Jenkins X could easily change the default format, because they have no compatibility commitment so far.

FTR, I did consider this strategy about keeping the current behavior, and introduce some sysprop to enable the new (and much much better, IMO) behavior.

But this is IMO not the way we provide the best possible Jenkins experience to users, especially newcomers. 

And I don't think we should consider Jenkins Essentials to be the only place where we make the OOTB experience as smooth as possible.

Do you really see a big issue if we offer a sysprop to revert to the current behavior, *but* change the default to something more sensible?

I fail to see how hard it would be for people having built monitoring about Jenkins logs to just temporarily use the sysprop while they adapt their logstash or whatever parsing rules. 

I can even probably provide it for logstash at least.

And again, this is IMO for the good of the project and its users, so even if there's some (small) disruption this is probably worth it.

Thanks a bunch for your feedback in any case.

-- Baptiste

[Oleg Nenashev]

Hi,

Please be sure I do not try to derail this story. Actually I think it is very important, especially if we could go beyond System logs. There are other log types in Jenkins (E.g. build logs), and in the modern CD/DevOps/whatever world it would be preferable to have some unified logging within the entire automation system. Yes, for the entire system, not just for Jenkins.

Creating automation-friendly system logging with Logstash/Fluentd support OOTB would definitely help to unify logging. For other log types there are stories like JENKINS-38313 "External Task Log Storage" which also lean towards such direction.

Thanks for sharing your thoughts Oleg, it makes me wonder: how could we
quantify the positive/negative impact of this (arguably) "bad default."I'm reminded of some of the pre-Jenkins 2 discussions about security defaults

The current logging format is bad for sure, nobody argues with that from what I see :)
 

for example. I spent some time trying to discover Jenkins-log-parsing projects,
tools, and their communities to which we could reach out. Unfortunately I
wasn't able to find anything big past a couple of blog posts :-/

WDYM? Parsing of system logs or logs in general?

 

And I don't think we should consider Jenkins Essentials to be the only place where we make the OOTB experience as smooth as possible.

Yes, we should not. But it definitely could be a place to start from.

1. We enable the new logging format in Essentials + immediately get benefit from it (e.g. via Logstash/fluentd)
   
2. We offer a feature flag in standard Jenkins. Start from opt-in, then maybe opt-out at some point
3. For installations passing through the installation wizard, we enable the feature by default (like we do with security defaults now)

BR, Oleg

 

--
You received this message because you are subscribed to a topic in the Google Groups "Jenkins Developers" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/jenkinsci-dev/4PTMMwQNfjw/unsubscribe.
To unsubscribe from this group and all its topics, send an email to jenkinsci-dev+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANWgJS48-5JTQKOSjt9dtFRimET-%3DH9JKGNh0OoWnKwq6QS0Gg%40mail.gmail.com.

[Daniel Beck]

> On 4. Apr 2018, at 21:20, Oleg Nenashev <o.v.ne...@gmail.com> wrote:
>
> • We enable the new logging format in Essentials + immediately get benefit from it (e.g. via Logstash/fluentd)

> • We offer a feature flag in standard Jenkins. Start from opt-in, then maybe opt-out at some point
> • For installations passing through the installation wizard, we enable the feature by default (like we do with security defaults now)
>

I'm conflicted about these. On the surface, this provides a compelling path forward with everyone getting what they want. However,

1. If we plan to allow opt-out in the end anyway, why start with opt-in? It's not a new subsystem that needs to be proven first. Good defaults are important, and letting those in the know who care deeply enable it for themselves might just delay the general implementation (perhaps indefinitely).
2. For this to be a setup wizard type distinction, it almost certainly needs to be promoted to a UI option (I think it would be the first wizard setting to not have one). I'm not positive this is a good idea.

[Jesse Glick]

On Wed, Apr 4, 2018 at 9:17 AM, Baptiste Mathus <m...@batmat.net> wrote:
> Instead of the usual:
>
> Apr 04, 2018 12:36:41 PM org.eclipse.jetty.util.log.Log initialized
> INFO: Logging initialized @354ms to org.eclipse.jetty.util.log.JavaUtilLog
> Apr 04, 2018 12:36:41 PM winstone.Logger logInternal
> INFO: Beginning extraction from war file

From this part of your message, what I suspect you are talking about
is the default logging format *in Winstone*. That is not a part of
Jenkins per se, nor is it controllable by code in Jenkins core. It is
specific to what appears on stderr when Jenkins is launched using
`java -jar jenkins.war`; when the WAR is loaded from other servlet
containers, they get to choose how log messages are presented. If you
wish to improve the default console format presented by Winstone, go
right ahead, but do not think that this is something that can be
controlled by the administrator except via Winstone command-line
options. There are already `--logfile`, `--logThrowingLineNo`,
`--logThrowingThread`, and `--debug` in this area.

As to the concrete format to pick, I do not have a strong opinion but
note that there is a compact one-line formatter in `support-core`
(later copied to `jenkins-test-harness` as well).

There is another place where a two-line format is displayed: in the
`LogRecorder` GUI, in `/log/all` for example. Certainly that could be
changed freely, since no one could (sanely) be depending on *that*.
Already it is colorized for readability, and you can do any HTML
tricks you like to present information nicely.

[gsim...@netflix.com]

> On Wednesday, April 4, 2018 at 9:12:39 AM UTC-7, Oleg Nenashev wrote:

> Anyone can easily change the logging format in Jenkins by passing custom J.U.L properties file.

I am going to go ahead and strongly disagree with the characterization that changing the logging is easy. I may be the only one that has ever struggled with getting custom logging for Jenkins but no one told the Jenkins Logging Wiki it was easy either:

Unfortunately, there is no simple way in Jenkins to send log messages generated by Jenkins himself or by any plugins to the console, to a file or anywhere else. No matter what command line options you will use, you just won't succeed.

Can you please please please share your secrets? 

[Daniel Beck]

> On 5. Apr 2018, at 23:24, gsimpson via Jenkins Developers <jenkin...@googlegroups.com> wrote:
>
> I am going to go ahead and strongly disagree with the characterization that changing the logging is easy. I may be the only one that has ever struggled with getting custom logging for Jenkins but no one told the Jenkins Logging Wiki it was easy either:
>
>> Unfortunately, there is no simple way in Jenkins to send log messages generated by Jenkins himself or by any plugins to the console, to a file or anywhere else. No matter what command line options you will use, you just won't succeed.
>
> Can you please please please share your secrets?

I'm not sure I understand the problem described in the wiki. I pieced together the following after a quick google search or two (i.e. these rules are probably mostly broken garbage):

> $ cat Desktop/logging.properties
> # Logging
> handlers = java.util.logging.FileHandler
> .level = ALL
>
> # File Logging
> java.util.logging.FileHandler.pattern = %h/jenkins.log
> java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
> java.util.logging.FileHandler.level = ALL
>
> java.util.logging.SimpleFormatter.format='%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS %4$s %2$s %5$s%6$s%n'
> $ java -Djava.util.logging.config.file=/Users/danielbeck/Desktop/logging.properties -jar ~/Jenkins/wars/jenkins-2.107.1.war

This works: It will create the file /Users/danielbeck/jenkins.log with extremely verbose content, in the custom one line format. I don't know what problems the wiki author encountered when they wrote this, but it seems wrong or obsolete.

[James Nord]

> Anyone can easily change the logging format in Jenkins by passing custom J.U.L properties file.

I know at least one person that did!

+1 to change the default. I think date&time should always come first though, not level and use a datetime format that does not have to cope with am/pm or crazy American date styles!

[Jesse Glick]

On Wed, Apr 11, 2018 at 10:01 AM, James Nord <james...@gmail.com> wrote:
> I think date&time should always come first though, not level and use a datetime format that does not have to cope with am/pm or crazy American date styles!

FTR the formatter in `support-core` produces output such as

2018-04-11 15:15:56.836+0000 [id=37] INFO
o.j.main.modules.sshd.SSHD#start: Started SSHD at port 2222

[Jesse Glick]

On Wed, Apr 11, 2018 at 11:18 AM, Jesse Glick <jgl...@cloudbees.com> wrote:

2018-04-11 15:15:56.836+0000 [id=37] INFO
o.j.main.modules.sshd.SSHD#start: Started SSHD at port 2222

Rrrgh, GMail line-wrapping without the RFC to preserve significant newlines. Trying again as HTML:

[Cyrille Le Clerc]

As I have already said many times, I fully support this initiative.

Tomcat has done this move a while ago and it was a great success.

Cyrille

On Wednesday, April 4, 2018 at 3:18:00 PM UTC+2, Baptiste Mathus wrote:

[Jesse Glick]

On Wed, Apr 4, 2018 at 8:18 PM Jesse Glick <jgl...@cloudbees.com> wrote:
> As to the concrete format to pick, I do not have a strong opinion but
> note that there is a compact one-line formatter in `support-core`
> (later copied to `jenkins-test-harness` as well).

https://github.com/jenkinsci/winstone/pull/63

[Gavin Williams]

Jesse

Unfortunately this appears to have broken the ability to provide a custom log format :( 

See https://issues.jenkins-ci.org/browse/JENKINS-57888 for more info... 

Ideas?

Cheers

Gavin 

[Jesse Glick]

On Fri, Jun 7, 2019 at 6:23 AM 'Gavin Williams' via Jenkins Developers
<jenkin...@googlegroups.com> wrote:
> Unfortunately this appears to have broken the ability to provide a custom log format :(
>
> See https://issues.jenkins-ci.org/browse/JENKINS-57888 for more info...

Seems like an RFE to me. `java -jar jenkins.war --help` does not
document any option to select a custom log format.

[Gavin Williams]

You're right that Jenkins doesn't provide details via help, but the method is documented on the Jenkins wiki, and is a standard Java mechanism of customising the logging output...

I can also see several mentions of the same method in this email thread... 

However the changes introduced have broken that method!

--
You received this message because you are subscribed to a topic in the Google Groups "Jenkins Developers" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/jenkinsci-dev/4PTMMwQNfjw/unsubscribe.

To unsubscribe from this group and all its topics, send an email to jenkinsci-de...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANfRfr0%2Bz%2B%3DgPAmYTT51wVdCLhifx5Q1HP_GR3pC7PSc1SLEOA%40mail.gmail.com.

[Jesse Glick]

Well, you can work on a PR to add a supported log format option to
`jenkinsci/winstone`.

[Gavin Williams]

Unfortunately Java dev is not my forte.. 

It's a shame this change was put in under the radar, with no changelog entry and no documentation update to define the new log format :( 

[Baptiste Mathus]

This was indeed an undocumented feature you and possibly others were relying on, this is it got broken without anyone realizing.

We are sorry about that, but so the right way to have this fixed is as Jesse was saying: please file a JIRA to explain the use case so we can possibly make a user-facing feature.

Aside: please refrain from using "shame" words in such case. I personally feel offended by such phrasing. 

This mailing list is an opensource developers mailing list, not a customer escalations channel.

Thanks

--

You received this message because you are subscribed to the Google Groups "Jenkins Developers" group.

To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-de...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/a8a2268d-48ba-4d7c-b876-9c44fb0f83ac%40googlegroups.com.

[Gavin Williams]

Baptiste/Jesse

Apologies if any of my comments come across as offensive. It was more out of frustraion that our log ingestion for Jenkins masterslogs was broken by an undocumented and unexpected change. 

I've filed a Jira as above - https://issues.jenkins-ci.org/browse/JENKINS-57888

Regards

You received this message because you are subscribed to a topic in the Google Groups "Jenkins Developers" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/jenkinsci-dev/4PTMMwQNfjw/unsubscribe.
To unsubscribe from this group and all its topics, send an email to jenkinsci-de...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-dev/CANWgJS47BVgA3qUtSroL%2BwE0o-LdQwM-gobwjKxjrttozdK8mw%40mail.gmail.com.