[hibernate-dev] Loggers

Tue Jan 15 10:14:26 EST 2019

Following the recent post about boot logging and recent work on a new
"module" (criteria queries) in 6, I wanted to circle back to this with a
few thoughts.  Now that this approach has been in place for quite a while
and has been getting used we have a better feel for how this works in
practice.

One thing I realized is that the use of symbolic names for the loggers
allows us to extend the idea of a "supported API" to logging as well.  What
I mean by this is that logging config would work from one release to the
next because we are using symbolic names rather than class names.  Even if
we did extensive refactoring moving classes to different packages, renaming
classes, etc... the logger names would stay the same.  Which is not a small
thing.  From a document I am working on:

== Logger/category names

Symbolic name versus FQN as logger/category name

Pros::

* Easier to configure as a hierarchy (imo);
* Safe from refactoring - which seems minor, but it makes logging config
something we could support, just as if it were an API

Cons::

* Easy for classes to use FQN instead of symbolic name

I personally really like moving TRACE and DEBUG logging to using this
approach as well.  It has worked really well in testing.  Its is so much
nicer to enable logging for query handling using:

log4j.logger.org.hibernate.orm.query=debug
log4j.logger.org.hibernate.orm.sql=debug

compared to:

log4j.logger.org.hibernate.hql=debug
log4j.logger.org.hibernate.loader=debug
log4j.logger.org.hibernate.sql=debug
log4j.logger.org.hibernate.type=debug
...

To be clear, there are also categories "under" the ones I used in the
example.  E.g. to see "query logging" just for HQL you'd use the
`log4j.logger.org.hibernate.orm.query.hql` (which has additional categories
as well (`log4j.logger.org.hibernate.orm.query.sqm.hql.parse.tree`, etc).
I wanted to make sure everyone is on board with this before we get too far
down this path - using symbolic names for TRACE/DEBUG logging.

One last thing I forgot to mention earlier is that this does require
changing the message ids.  The range for these ids are defined as part of
the message logger (the interface) via annotation.  As we move messages to
a different (modular) logger class the id range has to change.  This only
affects (is only supposed to affect[1]) message loggers (INFO/WARN/ERROR),
not info logging (TRACE/DEBUG).

[1] Historically we have only used message loggers (with ids) for
INFO/WARN/ERROR.  Some of the more recent changes by Guillaume change that
a bit and moved a few message logger messages to be DEBUG.  I think this is
another thing we should nail down moving forward - do we want TRACE/DEBUG
logging to potentially be messaged (with id) logs?

On Fri, Sep 28, 2018 at 10:46 AM Sanne Grinovero <sanne at hibernate.org>
wrote:

> On Fri, 28 Sep 2018 at 16:43, Steve Ebersole <steve at hibernate.org> wrote:
> >
> > Thanks for the feedback!
>
> I'm actually sorry for the delay :) Just back from 2 weeks off, catching
> up.
>
> > WRT effort, the plan is to make these changes as I do work in a
> particular area which is what I have been doing - not a "one shot, go back
> and change all logging".
>
> +1
>
> > WRT granularity, sure that would be a concern.  It really comes back to
> having a good "logical" design of the logger name hierarchy.
> >
> > WRT coordination, yep -
> https://github.com/sebersole/hibernate-core/blob/wip/6.0/logger_id_ranges.adoc
>
> Awesome!
>
> Thanks,
> Sanne
>
> >
> > On Fri, Sep 28, 2018 at 10:35 AM Sanne Grinovero <sanne at hibernate.org>
> wrote:
> >>
> >> Hi Steve,
> >>
> >> I love the cathegories idea; I think we discussed it before.  My only
> >> concern is that it's a lot of work to implement, but if you feel it's
> >> doable that's great.
> >>
> >> In terms of "changes needed" I'm not worried either. Like you said, 6
> >> would have had different names for most cases; at least moving forward
> >> such names would be more stable even if we decide to move some code in
> >> the future.
> >>
> >> One doubt is the granularity. I guess the risk is that maintainers
> >> will tend to reuse the same limited set of cathegories; we will need
> >> to make sure there are enough cathegories so that people can still
> >> enable the single aspect they might be interested in debugging, but
> >> maybe that's not important as people can always post-filter things
> >> when the output gets too verbose.
> >>
> >> We will need a way to coordinate on valid ranges for the various
> >> @ValidIdRange. Infinispan used a wiki for this; the upside is that
> >> it's out of the repository: a good thing to avoid reuse across repo
> >> branches - e.g. it's not ideal to have to change ids when backporting
> >> - , but downside of requiring human care.
> >>
> >> Thanks,
> >> Sanne
> >>
> >>
> >> On Wed, 19 Sep 2018 at 14:31, Steve Ebersole <steve at hibernate.org>
> wrote:
> >> >
> >> > Yes.  As I mentioned in my original, this would mean potential
> changes for
> >> > people configuring logging.  I've started doing this for new logging
> in 6
> >> > and it works great.
> >> >
> >> > Mainly asking opinions about changing existing logging and whether the
> >> > benefits are worth the effort.
> >> >
> >> > And keep in mind that the many many changes in 6 already would
> require such
> >> > logging config changes anyway for those configuring logging
> >> >
> >> >
> >> > On Wed, Sep 19, 2018, 12:50 AM Vlad Mihalcea <mihalcea.vlad at gmail.com
> >
> >> > wrote:
> >> >
> >> > > I think it's a good idea.
> >> > >
> >> > > However, will this break all current applications that use the
> package
> >> > > name log appenders?
> >> > >
> >> > > Vlad
> >> > >
> >> > > On Fri, Sep 14, 2018 at 7:20 PM, Steve Ebersole <
> steve at hibernate.org>
> >> > > wrote:
> >> > >
> >> > >> Yes, I know no one likes talking about logging.  "Its not
> important",
> >> > >> until
> >> > >> it is ;)
> >> > >>
> >> > >> TLDR I am considering moving to using "module names" for logger
> names
> >> > >> instead of Class names even for DEBUG/TRACE logging and see if
> anyone had
> >> > >> strong arguments to not do this..
> >> > >>
> >> > >> Full version---
> >> > >>
> >> > >> For some time I have been moving to an approach of defining message
> >> > >> loggers[1] using a single contract per function or "module" - e.g.:
> >> > >>
> >> > >>    1. the second level caching module uses the dedicated message
> logger
> >> > >>    `ConnectionPoolingLogger`
> >> > >>    2. the ManagedBeanRegistry module uses the dedicated message
> logger
> >> > >>    `BeansMessageLogger`
> >> > >>    3. etc
> >> > >
> >> > >
> >> > >>
> >> > >> Each of these define a dedicate instance instance they can use.
> E.g.
> >> > >> ConnectionPoolingLogger is defined as:
> >> > >>
> >> > >> ````
> >> > >> @MessageLogger( projectCode = "HHH" )
> >> > >> @ValidIdRange( min = 10001001, max = 10001500 )
> >> > >> public interface ConnectionPoolingLogger extends BasicLogger {
> >> > >>
> >> > >> ConnectionPoolingLogger CONNECTIONS_LOGGER =
> Logger.getMessageLogger(
> >> > >> ConnectionPoolingLogger.class,
> >> > >> "org.hibernate.orm.connections.pooling"
> >> > >> );
> >> > >>
> >> > >> ...
> >> > >> }
> >> > >> ````
> >> > >>
> >> > >> I won't get into all the whys I do this unless someone cares ;)
> >> > >>
> >> > >> But I am contemplating doing the same for basic loggers so I
> wanted to ask
> >> > >> everyone else's opinion since this means a change in how you'd
> have to
> >> > >> configure logging for DEBUG/TRACE output.  Usually you'd use the
> Class
> >> > >> name
> >> > >> as the logger name and use that to control logging in the back-end
> (log4j,
> >> > >> etc).  If I do this, you'd have to instead use the module name.
> >> > >>
> >> > >> There are quite a few reasons I am considering  this, including
> all of the
> >> > >> reasons I did it for  message loggers in the first place.  If I am
> >> > >> debugging the loading of a collection or an entity, today I'd have
> to know
> >> > >> all the packages involved (there is no common root name) and list
> them in
> >> > >> my log4j.properties; that is because the process is ultimately
> handled by
> >> > >> delegates or helpers in many different packages
> (`org.hibernate.loader`,
> >> > >> `org.hibernate.persister`, `org.hibernate.type`, ...).  It sure
> would be
> >> > >> nice to just be able to say `org.hibernate.loading` or
> >> > >> `org.hibernate.loading.entity` or
> `org.hibernate.loading.collection` or
> >> > >> ...
> >> > >> for a number of reasons:
> >> > >>
> >> > >>    1. When we need to see logging from someone it is a lot easier
> to tell
> >> > >>    the module name(s) you need enabled as opposed a list of
> package and
> >> > >> class
> >> > >>    names.
> >> > >>    2. When running JPA TCK it is essentially impossible to attach
> debugger
> >> > >>    to step through code when debugging a failure - you have to
> rely on
> >> > >>    debugging through output.  *Well that used to be the case, but
> the
> >> > >>    latest TCK broke logging to STDOUT somehow so we ended up
> having to
> >> > >> try and
> >> > >>    reproduce the failure in our testsuite - so then it does not
> matter
> >> > >> either
> >> > >>    way ;)*
> >> > >>    3. Easier to document -
> >> > >>
> >> > >>
> http://docs.jboss.org/hibernate/orm/5.3/topical/html_single/logging/Logging.html
> >> > >>
> >> > >> Thoughts?
> >> > >>
> >> > >>
> >> > >> [1] JBoss Logging's `org.jboss.logging.annotations.MessageLogger`
> - which
> >> > >> we use for user-focused log messages.  Should always be logged at
> >= INFO
> >> > >> [2]
> >> > >> [3] JBoss Logging's `org.jboss.logging.BasicLogger` - which we use
> for
> >> > >> developer-focused log messages (for debugging).  Should always be
> logged
> >> > >> at
> >> > >> DEBUG or TRACE
> >> > >> _______________________________________________
> >> > >> hibernate-dev mailing list
> >> > >> hibernate-dev at lists.jboss.org
> >> > >> https://lists.jboss.org/mailman/listinfo/hibernate-dev
> >> > >>
> >> > >
> >> > >
> >> > _______________________________________________
> >> > hibernate-dev mailing list
> >> > hibernate-dev at lists.jboss.org
> >> > https://lists.jboss.org/mailman/listinfo/hibernate-dev
>