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] <javascript:>> > 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] <javascript:>> >> 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] <javascript:> >>> >>> --- >>> 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] <javascript:>. >>> 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.
