Just checked new integration tests for 1.11.5-SNAPSHOT and 2.0.0-SNAPSHOT - all is fine. So I'm backporting this change to pax-logging 1.10.x (without tests...)
regards Grzegorz Grzybek czw., 2 sty 2020 o 17:42 Monica Ron <[email protected]> napisał(a): > I am glad you were able to reproduce the issue and see what I meant. > > Yes, please backport the fix to 1.10.x. I tried the fix for PAXLOGGING-306 > for getting the pax-logging-log4j2 in the 1.10.x branch to print stack > traces, and it worked--my stack traces were printed correctly. So, if this > issue PAXLOGGING-307 for losing track of loggers is also fixed in 1.10.x, > it would be much appreciated. > > Thanks again! > Monica > > On Thursday, January 2, 2020 at 11:32:07 AM UTC-5, Grzegorz Grzybek wrote: > >> 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/96f01aae-bbb3-4b76-bcc8-9b9f050d1e4a%40googlegroups.com > <https://groups.google.com/d/msgid/ops4j/96f01aae-bbb3-4b76-bcc8-9b9f050d1e4a%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/CAAdXmhpeEue5CpB68K6W8eyTN%3DRTkuD0BRW7U_%2BYyBEKwv446w%40mail.gmail.com.
