Hello Monica I've fixed https://ops4j1.jira.com/browse/PAXLOGGING-307 and while pax-logging 1.11.x and 2.0.x have proper tests, there are no such tests in 1.10.x. And also 1.10.x is not the version I was refactoring. So - may I ask you kindly to check https://github.com/ops4j/org.ops4j.pax.logging/commits/pax-logging-1.10.x branch if it solves your problem?
regards Grzegorz Grzybek czw., 2 sty 2020 o 17:48 Grzegorz Grzybek <[email protected]> napisał(a): > 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/CAAdXmhpKY9nmYH80ZV1TSr8a_-Z37_%3DDSaN5tGU2Aq3WozGPpQ%40mail.gmail.com.
