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/CAAdXmhqGGzxLErOsZttz-_ypYyjrj1SUVdDP_Fp7afs8ipasZQ%40mail.gmail.com.
