Hello
Thanks for describing the problem in such details!
I reproduced the problem and indeed - simple:
Logger log1a = LoggerFactory.getLogger(this.getClass());
Logger log1b = LoggerFactory.getLogger(this.getClass());
(getting same logger twice), when pax-logging-api is not yet started gives
me two instances of org.ops4j.pax.logging.slf4j.Slf4jLogger, but only one
is cached in (now global)
org.ops4j.pax.logging.internal.Activator#m_loggers.
I changed this org.ops4j.pax.logging.internal.Activator#m_loggers map to
... list and it works fine ;) Both the above loggers have their m_delegate
replaced when pax-logging-api starts.
What's more - I added special unit test (in pax-logging 1.11.x+) to prove
this. But I can also backport the fix to pax-logging 1.10.x.
What's even more, here's resulting behavior:
1) when pax-logging-api is not yet started:
- all bundles starting "earlier" can already use any logging facade
provided by (not even started) pax-logging-api - pax-logging-api needs to
be at least resolved, otherwise other bundles would not be resolved too.
- all obtained loggers use underlying m_delegate set to DefaultServiceLog
2) when pax-logging-api finally starts:
- all bundles added to (now a list)
org.ops4j.pax.logging.internal.Activator#m_loggers have their
org.ops4j.pax.logging.PaxLoggingManagerAwareLogger#setPaxLoggingManager()
method called and underlying m_delegate switched from DefaultServiceLog to
TrackingLogger obtained from
org.ops4j.pax.logging.OSGIPaxLoggingManager#getLogger() and
org.ops4j.pax.logging.internal.Activator#m_loggers is cleared! because we
no longer need to replace underlying m_delegate
- these underlying TrackingLoggers will switch back and forth between
DefaultServiceLog and actual PaxLoggerImpl when
pax-logging-log4j1/pax-logging-log4j2/pax-logging-logback bundles are
restarted OR refreshed
3) when pax-logging-api stops
- org.ops4j.pax.logging.internal.Activator#m_loggers is already empty, so
nothing is done in this list
- however org.ops4j.pax.logging.OSGIPaxLoggingManager#m_loggers is not
empty - it contains ALL tracking loggers for all facades. These loggers
have their m_delegate switched back to DefaultServiceLog
Conclusion:
- loggers do NOT switch again to TrackingLoggers when pax-logging-api
starts again
- the above COULD be improved if
org.ops4j.pax.logging.OSGIPaxLoggingManager#m_loggers was static, but:
- I think stopping pax-logging-api is not something that should be done
frequently
- loggers would still be "disconnected" when pax-logging-api is
REFRESHED - but this would lead to refresh of almost everything... So we
could consider preserving the map of TrackingLoggers in the future
- loggers switch to proper m_delegate when
pax-logging-log4j1/pax-logging-log4j2/pax-logging-logback restarts/refreshes
regards
Grzegorz Grzybek
czw., 2 sty 2020 o 15:48 Grzegorz Grzybek <[email protected]> napisał(a):
> Hello
>
> I created https://ops4j1.jira.com/browse/PAXLOGGING-307 to track this
> issue.
>
> regards
> Grzegorz Grzybek
>
> pon., 9 gru 2019 o 22:35 Monica Ron <[email protected]> napisał(a):
>
>> Thanks. If you do change the code to fix my problem (e.g., swap order of
>> the generic parameters, or whatever other way you fix it), I hope you can
>> release a 1.10.x as well as fixing it on the newer 1.11.x, since I can't
>> use 1.11.x yet.
>>
>> I can't even use 1.10.4, as I'm having trouble with a NoSuchMethodError
>> in some of the pax-logging-log4j2 when printing stack traces. I'll submit a
>> bug in Jira for that. I didn't try 1.10.3, but 1.10.2 works for printing
>> stack traces.
>>
>> Monica
>>
>> On Friday, December 6, 2019 at 12:44:12 AM UTC-5, Grzegorz Grzybek wrote:
>>>
>>> Hello
>>>
>>> Thank you for this analysis - you are correct.
>>> The goal of removing map-per-logging facade was to unify logging
>>> behavior and allowing two bundles to use two different loggers with the
>>> same name (though now I think the problem was caused by this generification
>>> you've mentioned).
>>>
>>> There's also
>>> https://github.com/ops4j/org.ops4j.pax.logging/blob/logging-1.11.3/pax-logging-it/src/test/java/org/ops4j/pax/logging/it/Log4J2RestartBothPaxLoggingBundlesIntegrationTest.java
>>> test that shows what happens when logger was obtained and
>>> pax-logging-api+pax-logging-log4j2 bundles were restarted.
>>>
>>> I added a comment that when logger is obtained when pax-logging-api is
>>> ACTIVE and then it's stopped, it WON'T be reconnected to a backend.
>>> Though it seems
>>> <https://github.com/ops4j/org.ops4j.pax.logging/blob/logging-1.11.3/pax-logging-it/src/test/java/org/ops4j/pax/logging/it/Log4J2RestartBothPaxLoggingBundlesIntegrationTest.java>
>>> that if logger was obtained when pax-logging-api is stopped (INSTALLED
>>> state), then it WILL be reconnected to actual backend...
>>>
>>> From your description, I believe I can check your problem, but not this
>>> week.
>>>
>>> regards
>>> Grzegorz Grzybek
>>>
>>> pt., 6 gru 2019 o 03:57 Monica Ron <[email protected]> napisał(a):
>>>
>>>> I got the tests to run, but I am still working on modifying them to
>>>> illustrate my problem. It is clear to me from studying the pax logging code
>>>> and observing its behavior that having the m_loggers maps (whether per
>>>> logging API or as a single global map) with key=name and value=logger is
>>>> wrong, and can cause some loggers to get stuck with DefaultServiceLog.
>>>> However, I don't know yet know how to show it in a unit test.
>>>>
>>>> What happens in my Glassfish/Payara setup is:
>>>> 1. Wars that were already deployed when Payara is restarted start up
>>>> first (before the pax logging bundles are started up), with pax-logging-api
>>>> and pax-logging-log4j2 on the classpath, but those pax bundles haven't been
>>>> activated yet (the Activator class has not run).
>>>>
>>>> 2. During #1, the JclLogger and Slf4jLogger get a DefaultServiceLog
>>>> instance, because they can see the unactivated pax-logging-api code. I
>>>> don't use either of these directly (our code uses Log4J2), but Mongo uses
>>>> SLF4J, and Spring uses JCL. During startup of my wars, Mongo uses the same
>>>> name multiple times when getting loggers, and Spring uses the same name
>>>> multiple times for getting loggers. This is based on Mongo and Spring
>>>> behavior (not mine). As I described, when the name is used a second time,
>>>> the new JclLogger (or Slf4jLogger) replaces the first JclLogger/Slf4jLogger
>>>> as a value in the m_loggers map. When m_loggers.put(name, jclLogger) is
>>>> called, the previous JclLogger is returned (standard behavior of the "put"
>>>> method on a map), and the second (or subsequent, as some come up many
>>>> times) time "put" is called, the return value of "put" is not null.
>>>>
>>>> 3. Payara goes to OSGi start level 2, and activates pax-logging-api by
>>>> running Activator, and the JclLogger/Slf4jLogger instances that are in the
>>>> m_loggers maps get updated with a TrackingLogger instead of the original
>>>> DefaultServiceLog. Then when pax-logging-log4j2 is activated, the
>>>> JclLogger/Slf4jLogger instances log through the pax logging, based on my
>>>> settings in org.ops4j.pax.logging.cfg. The JclLogger and Slf4jLogger
>>>> instances that got removed from the map in #2 still use the
>>>> DefaultServiceLog, not a TrackingLogger, because the Activator does not
>>>> know that these instances exist. Mongo logs some status data every few
>>>> minutes, and some of that still uses the DefaultServiceLog, because the
>>>> name was used multiple times. The DefaultServiceLog does not respect my
>>>> configuration that says "don't log this status data [it's at "debug" level,
>>>> and I set that category to "info" level, but my setting is ignored]. Some
>>>> Spring code also does not respect my configuration, because some instances
>>>> of the logger still uses DefaultServiceLog.
>>>>
>>>> 4. With Payara now up and running with pax-logging-api and
>>>> pax-logging-log4j2 fully activated, if I redeploy my war, all instances of
>>>> JclLogger/Slf4jLogger immediately get TrackingLogger (no
>>>> DefaultServiceLog), and log based on my org.ops4j.pax.logging.cfg. The
>>>> Mongo status logging at debug level and the Spring logging that I don't
>>>> want now goes away.
>>>>
>>>> 5. If I restart the domain again, the whole thing starts over--I get
>>>> stuck with DefaultServiceLog until I redeploy the war while pax-logging-api
>>>> and pax-logging-log4j2 are fully activated.
>>>>
>>>>
>>>> If I run a profiler (e.g., jvisualvm) on my process, I can see lots of
>>>> DefaultServiceLog instances still exist after Step #3. After Step #4, many
>>>> of those DefaultServiceLog instances go away, because the re-deployed war
>>>> uses only TrackingLogger (because pax-logging-api is already running). If
>>>> pax-logging was properly replacing all DefaultServiceLog with the
>>>> TrackingLogger, then Step #3 (as soon as pax-logging-api got activated),
>>>> then I think *all* of the DefaultServiceLog instances should go away.
>>>>
>>>> If m_loggers was stored as key=logger, value=name (as it did before
>>>> someone added generics in December 2015), then when iterating through the
>>>> loggers in Activator (would iterate over the keys, not the values), the
>>>> Activator would still be able to see *all* instances of loggers that ever
>>>> got created, instead of losing some of them (losing them when name is
>>>> repeated, if name is the key).
>>>>
>>>> ===========
>>>> I tried running the SimplestPaxLoggingServiceIntegrationTest, but as
>>>> soon as the test starts, the logger already uses a TrackingLogger (not the
>>>> DefaultServiceLog). That is, by the time the test starts, the
>>>> pax-logging-api has already been activated. I need to run a test that
>>>> creates two or more loggers with the same name *before* pax-logging-api
>>>> Activator gets called. I can't tell if there are any tests that mimic my
>>>> situation of getting loggers before the pax-logging-api is activated (so
>>>> that the DefaultServiceLog is used), and then activating it as part of the
>>>> test (so that the DefaultServiceLog is replaced with TrackingLogger during
>>>> the test run).
>>>>
>>>> Monica
>>>>
>>>> --
>>>> --
>>>> ------------------
>>>> OPS4J - http://www.ops4j.org - [email protected]
>>>>
>>>> ---
>>>> You received this message because you are subscribed to the Google
>>>> Groups "OPS4J" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to [email protected].
>>>> To view this discussion on the web visit
>>>> https://groups.google.com/d/msgid/ops4j/80cf1c6a-db69-4463-b85a-5b2b112a27f6%40googlegroups.com
>>>> <https://groups.google.com/d/msgid/ops4j/80cf1c6a-db69-4463-b85a-5b2b112a27f6%40googlegroups.com?utm_medium=email&utm_source=footer>
>>>> .
>>>>
>>> --
>> --
>> ------------------
>> OPS4J - http://www.ops4j.org - [email protected]
>>
>> ---
>> You received this message because you are subscribed to the Google Groups
>> "OPS4J" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to [email protected].
>> To view this discussion on the web visit
>> https://groups.google.com/d/msgid/ops4j/132b64d3-6418-47b0-85f7-fd7b9199b8d9%40googlegroups.com
>> <https://groups.google.com/d/msgid/ops4j/132b64d3-6418-47b0-85f7-fd7b9199b8d9%40googlegroups.com?utm_medium=email&utm_source=footer>
>> .
>>
>
--
--
------------------
OPS4J - http://www.ops4j.org - [email protected]
---
You received this message because you are subscribed to the Google Groups
"OPS4J" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/ops4j/CAAdXmhrox48WWk395em%3DFUQdS4SBhCF%3DJGzVwdUg6SRv-1r%2BhQ%40mail.gmail.com.
