11:20 a.m.
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/Loggi...
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
8:20 a.m.
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(a)gmail.com>
wrote:
10:29 a.m.
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(a)hibernate.org> wrote:
10:42 a.m.
Thanks for the feedback!
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".
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...
On Fri, Sep 28, 2018 at 10:35 AM Sanne Grinovero <sanne(a)hibernate.org>
wrote:
10:46 a.m.
On Fri, 28 Sep 2018 at 16:43, Steve Ebersole <steve(a)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
Awesome!
Thanks,
Sanne
9:14 a.m.
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(a)hibernate.org>
wrote:
6:19 a.m.
Hi Steve,
thanks that looks very nice; sub- hierarchies also look great.
My only oncern is with the mentioned need to change Logger range IDs;
can we handle this in such a way to avoid recycling of previous IDs?
Maybe the simplest solution is to use the ORM6 release as an
opportunity to change the logger prefix? (No longer HHH ?)
Alternatively we could pick new ranges; hopefully numbers don't get
too silly :)
Thanks,
Sanne
On Tue, 15 Jan 2019 at 15:14, Steve Ebersole <steve(a)hibernate.org> wrote:
2262
days inactive
2386
days old
7 comments
3 participants
participants (3)
-
Sanne Grinovero -
Steve Ebersole -
Vlad Mihalcea