6:20 p.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
7:49 a.m.
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(a)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(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/hibernate-dev
3:20 p.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:
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(a)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/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
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev(a)lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>
5:29 p.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:
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:
> 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(a)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/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
>> _______________________________________________
>> hibernate-dev mailing list
>> hibernate-dev(a)lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>
>
>
_______________________________________________
hibernate-dev mailing list
hibernate-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/hibernate-dev
5:42 p.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:
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:
>
> 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:
>
> > 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(a)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/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
> >> _______________________________________________
> >> hibernate-dev mailing list
> >> hibernate-dev(a)lists.jboss.org
> >> https://lists.jboss.org/mailman/listinfo/hibernate-dev
> >>
> >
> >
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev(a)lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev
5:46 p.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
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...
Awesome!
Thanks,
Sanne
On Fri, Sep 28, 2018 at 10:35 AM Sanne Grinovero <sanne(a)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(a)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(a)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(a)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/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
> > >> _______________________________________________
> > >> hibernate-dev mailing list
> > >> hibernate-dev(a)lists.jboss.org
> > >> https://lists.jboss.org/mailman/listinfo/hibernate-dev
> > >>
> > >
> > >
> > _______________________________________________
> > hibernate-dev mailing list
> > hibernate-dev(a)lists.jboss.org
> > https://lists.jboss.org/mailman/listinfo/hibernate-dev
4:14 p.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:
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
> 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...
Awesome!
Thanks,
Sanne
>
> On Fri, Sep 28, 2018 at 10:35 AM Sanne Grinovero <sanne(a)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(a)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(a)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(a)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/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
>> > >> _______________________________________________
>> > >> hibernate-dev mailing list
>> > >> hibernate-dev(a)lists.jboss.org
>> > >> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>> > >>
>> > >
>> > >
>> > _______________________________________________
>> > hibernate-dev mailing list
>> > hibernate-dev(a)lists.jboss.org
>> > https://lists.jboss.org/mailman/listinfo/hibernate-dev
1:19 p.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:
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:
>
> 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
>
> > 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...
>
> Awesome!
>
> Thanks,
> Sanne
>
> >
> > On Fri, Sep 28, 2018 at 10:35 AM Sanne Grinovero <sanne(a)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(a)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(a)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(a)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/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
> >> > >> _______________________________________________
> >> > >> hibernate-dev mailing list
> >> > >> hibernate-dev(a)lists.jboss.org
> >> > >> https://lists.jboss.org/mailman/listinfo/hibernate-dev
> >> > >>
> >> > >
> >> > >
> >> > _______________________________________________
> >> > hibernate-dev mailing list
> >> > hibernate-dev(a)lists.jboss.org
> >> > https://lists.jboss.org/mailman/listinfo/hibernate-dev
1926
days inactive
2050
days old
7 comments
3 participants
participants (3)
-
Sanne Grinovero -
Steve Ebersole -
Vlad Mihalcea