Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jetty logging supporting Throwable as last argument #4567

Closed
sbordet opened this issue Feb 12, 2020 · 17 comments · Fixed by #4570 or #4596
Closed

Jetty logging supporting Throwable as last argument #4567

sbordet opened this issue Feb 12, 2020 · 17 comments · Fixed by #4570 or #4596
Assignees

Comments

@sbordet
Copy link
Contributor

sbordet commented Feb 12, 2020

Jetty version
10.0.x

Description
Like other logging frameworks, would be handy if Jetty logging (StdErrLog) could detect whether the last argument is a Throwable and if so print its stack trace.

In this way one could write:

logger.debug("Log {}", this, new Throwable());

rather than:

logger.debug("Log " + this, new Throwable())
@joakime joakime self-assigned this Feb 12, 2020
@sbordet
Copy link
Contributor Author

sbordet commented Feb 12, 2020

@joakime perhaps we can review the API and completely drop those that have an explicit Throwable last parameter, keeping just Object...?

@joakime
Copy link
Contributor

joakime commented Feb 12, 2020

Some other logging APIs. (they actually use Throwable as the last argument)

@sbordet
Copy link
Contributor Author

sbordet commented Feb 12, 2020

Some other logging APIs. (they actually use Throwable as the last argument)

Yes, but there is no need to if you probe the last argument. One API only (Object...) does everything is needed.

@gregw
Copy link
Contributor

gregw commented Feb 12, 2020

If we are changing logging, should we switch to String.format style rather than {} style?

@joakime
Copy link
Contributor

joakime commented Feb 12, 2020

The {} style is the facade API that all loggers use, not just StdErrLog, but also Slf4jLog and JavaUtilLog

@joakime
Copy link
Contributor

joakime commented Feb 12, 2020

If we are entertaining the cleanup of the logging API, how about we just drop all of Jetty logging and use slf4j-api everywhere.
We could then just implement a slf4j-impl that is our StdErr output (a JettyStdErrSlf4jImpl which does our formatted output)?

I think this is a good direction to go, and should also have a positive impact (simplifying) on our jetty-home logging modules.

@olamy
Copy link
Member

olamy commented Feb 13, 2020

@joakime good idea! worth to try but no more LOG.ignore?

@joakime
Copy link
Contributor

joakime commented Feb 13, 2020

Proposal

Drop org.eclipse.jetty.util.log

The entire package org.eclipse.jetty.util.log is deleted

Create jetty-slf4j-impl module

A new module called jetty-slf4j-impl is created.

This module performs the equivalent to Jetty's StdErrLog.

  • Same output formatting as StdErrLog in 9.x
  • Supports jetty-logging.properties for configuring logging levels

It has a META-INF/services/org.slf4j.spi.SLF4JServiceProvider

A package space of org.eclipse.jetty.logging
A JPMS of jetty-logging ?

This new module would be included as a <scope>test</scope>
across the other Jetty modules that need it for testing.

Migrate logging properties

Existing properties

  • org.eclipse.jetty.util.log.class (classname, default "org.eclipse.jetty.util.log.Slf4jLog") - use to select the logger
  • org.eclipse.jetty.util.log.announce (boolean, default "true") - used to control announcement text "Logging to {} via {}"
  • org.eclipse.jetty.util.log.IGNORED (boolean, default "false") - used to control if Log.ignored() should be shown or not
  • org.eclipse.jetty.util.log.StdErrLog.TAG_PAD (number, default "0") - used for minimum padding width of the Thread.name
  • org.eclipse.jetty.util.log.SOURCE (boolean, default "false") - used as default for showing of source (filename and line number) in stacktraces
  • org.eclipse.jetty.util.log.stderr.SOURCE (boolean, default "false") - used for showing of source (filename and line number) in stacktraces
  • org.eclipse.jetty.util.log.stderr.LONG (boolean, default "false") - used for condensing the logger name package
  • org.eclipse.jetty.util.log.stderr.ESCAPE (boolean, default "true") - used for escaping the output of the logger message.

Dropped properties

  • org.eclipse.jetty.util.log.class - controlled by slf4j-api now
  • org.eclipse.jetty.util.log.announce - controlled by slf4j-api now
  • org.eclipse.jetty.util.log.SOURCE - we only have 1 logger now.

Renamed properties

  • org.eclipse.jetty.logging.IGNORED (boolean, default "true") - used to control if Log.ignored() should be shown or not
  • org.eclipse.jetty.logging.THREAD_PADDING (number, default "0") - used for minimum padding width of the Thread.name
  • org.eclipse.jetty.logging.SOURCE (boolean, default "false") - used for showing of source (filename and line number) in stacktraces
  • org.eclipse.jetty.logging.NAME_CONDENSE (boolean, default "true") - used for condensing the logger name package
  • org.eclipse.jetty.logging.MESSAGE_ESCAPE (boolean, default "true") - used for escaping the output of the logger message

Migrate source to use slf4j

Migrate code from ...

import org.eclipse.jetty.util.log.Log;
import org.eclipse.jetty.util.log.Logger;

private static final Logger LOG = Log.getLogger(DoSFilter.class);

... to ...

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

private static final Logger LOG = LoggerFactory.getLogger(DoSFilter.class);

The usage of Log.ignore(Throwable) would need to be migrated as well.

LOG.trace("IGNORED", cause);

The org.eclipse.jetty.util.StacklessLogging would be moved to
org.eclipse.jetty.logging.StacklessLogging (in the new jetty-slf4j-impl
module) to provide the same behaviors as before for testing.

New logging modules for jetty-home

The existing logging modules in Jetty 9.4.x are ...

  • console-capture.mod
  • jcl-slf4j.mod
  • jul-impl.mod
  • jul-slf4j.mod
  • log4j2-api.mod
  • log4j2-impl.mod
  • log4j2-slf4j.mod
  • log4j-impl.mod
  • logback-impl.mod
  • logging-jetty.mod
  • logging-jul.mod
  • logging-log4j.mod
  • logging-log4j2.mod
  • logging-logback.mod
  • logging-slf4j.mod
  • slf4j-api.mod
  • slf4j-jul.mod
  • slf4j-log4j.mod
  • slf4j-log4j2.mod
  • slf4j-logback.mod
  • slf4j-simple-impl.mod

We would simplify this a great deal to just ...

  • console-capture.mod
  • logging-jetty.mod
  • logging-jul.mod
  • logging-log4j.mod
  • logging-log4j2.mod
  • logging-logback.mod

Where each logging module captures all logging implementations
via the various slf4j bridge jars, and enables the appropriate
slf4j implementation jar based on your logging module selection.

The new modules would also no longer force a forking of a JVM.

@jmcc0nn3ll
Copy link
Contributor

Any special configuration challenges to capturing and directing webapp logging?

@sbordet
Copy link
Contributor Author

sbordet commented Feb 13, 2020

Had a look at System.Logger APIs, whether we can use those instead of SLF4J now that they are in JDK 11.

But no, they lack features like MDC and the APIs require to pass a Level as first parameter (log(DEBUG, ...) rather than debug(...)) - not ideal.

I think the big overhaul of the logging would be a good change, but for Jetty 12.

For Jetty 10, probing just the last parameter should be simple and small enough.

@joakime
Copy link
Contributor

joakime commented Feb 13, 2020

Any special configuration challenges to capturing and directing webapp logging?

It would just be a configuration of the WebAppContext / WebAppClassLoader and its ClasspathPattern (Server & System) to support that.
We could have that be a module / configuration as well. something called webapp-centralized-logging

joakime added a commit that referenced this issue Feb 13, 2020
Checkstyle fixes ...
+ Log.__loggers now Log.LOGGERS
+ Log.__props now Log.PROPS
+ StdErrLog.__tagpad now StdErrLog.THREADNAME_PADDING
+ StdErrLog.__source now StdErrLog.SOURCE
+ StdErrLog.__long now StdErrLog.LONG_CLASSNAMES
+ StdErrLog.__escape now StdErrLog.ESCAPE_CONTROL_CHARS
+ Removed redundant "public" modifier on Log interface methods

New code ...
+ New Log.getProperty(String key, String defaultValue)
  Used by JavaUtilLog, JettyLogHandler, and StdErrLog
+ New StdErrLog.getConfiguredLevel()
+ New StrErrLog.println(String) used to write StringBuilder
  to configured PrintStream

Removed code ...
+ Removed deprecated prop check in StdErrLog initialization

Cleanup and Corrected code ...
+ StdErrLog.setDebugEnabled(boolean) cleanup
+ StdErrLog._stderr is now used and is never null
+ Only one StdErrLog.format() method entry point
+ StdErrLog.format(StringBuilder, Throwable) now called .formatCause(StringBuilder, Throwable, String)

Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
@gregw
Copy link
Contributor

gregw commented Feb 14, 2020

I like the proposed change to direct use of log4j, but I don't think we can go directly there without deprecating the existing mechanism.

However, I do think within 10/11 we can change to using log4j directly and deprecate the old API, then 12 we can remove the old API. Means we still have some module complexity for a while.. at least in the naming, but the contents should become simpler. If we do it this way, no need to hold up 10.0.0 for this to be implemented.

So let's just go with sniffing the last param for now.

@joakime
Copy link
Contributor

joakime commented Feb 14, 2020

log4j1 is not very performant and is abandoned now.
log4j2 is too bleeding edge, is still unstable, and has a history of JVM hanging issues.

Opened PR #4570 for the last argument sniffing for Throwable.

The time needed to make the change in the Proposal is only about 2 days.

@joakime
Copy link
Contributor

joakime commented Feb 14, 2020

Opened Issue #4572 to track the larger Proposal separately

@gregw
Copy link
Contributor

gregw commented Feb 15, 2020

ooops did I say log4j, I meant slf4j! slf4j is just a facade like our own Logging API, so it essentially gives us the same flexibility, but with less complexity at the small cost of an API jar dependency.

joakime added a commit that referenced this issue Feb 18, 2020
Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
joakime added a commit that referenced this issue Feb 19, 2020
…ng "null")

Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
joakime added a commit that referenced this issue Feb 20, 2020
Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
joakime added a commit that referenced this issue Feb 20, 2020
…owable

Issue #4567 - StdErrLog cleanup and final Arg Throwable support
@joakime
Copy link
Contributor

joakime commented Feb 20, 2020

Reopening for Jetty 9.4.x too

@joakime joakime reopened this Feb 20, 2020
joakime added a commit that referenced this issue Feb 20, 2020
Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
joakime added a commit that referenced this issue Feb 20, 2020
Signed-off-by: Joakim Erdfelt <joakim.erdfelt@gmail.com>
joakime added a commit that referenced this issue Feb 20, 2020
…lastarg

Issue #4567 - Backport of StdErrLog 10.0.x for Throwable behavior change
@joakime
Copy link
Contributor

joakime commented Feb 22, 2020

PR #3596 merged.

@joakime joakime closed this as completed Feb 22, 2020
@joakime joakime changed the title Jetty logging Throwable last argument Jetty logging supporting Throwable as last argument Feb 26, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment