uPortal IRC Logs-2013-09-27

[09:47:55 CDT(-0500)] <jgribonvald> hi all

[09:48:28 CDT(-0500)] <jgribonvald> I have a question about one issue : https://issues.jasig.org/browse/UP-3701

[09:48:40 CDT(-0500)] <jgribonvald> mainly it's to tlev

[09:49:13 CDT(-0500)] <jgribonvald> do you have an example of the error ?

[09:49:37 CDT(-0500)] <tlev> hmm, i would have to check and see if we documented the exact error message

[09:51:18 CDT(-0500)] <jgribonvald> ok thanks

[09:52:21 CDT(-0500)] <jgribonvald> because we would like to reactivate normal login on uportal-war/src/main/java/org/jasig/portal/utils/threading/DoubleCheckedCreator.java

[09:52:30 CDT(-0500)] <jgribonvald> to gain 1s per login

[09:53:40 CDT(-0500)] <jgribonvald> I would like to check if we get your error as we tested and it seems that we don't get a related error

[09:54:05 CDT(-0500)] <jgribonvald> we are testing only on this class a normal logger

[09:54:17 CDT(-0500)] <jgribonvald> like it was done before

[10:03:28 CDT(-0500)] <tlev> The problem exists because we are using the webapprootkey feature in the web.xml which is used in the logging properties. If you try to initialize a class that declares a logger before that webapprootkey listener is setup then you have logging issues. We could make it a bit smarter and have an "initialize" class which would create a one time logger on first pass, and then just pass back that same instance on each subsequent call.

[10:04:01 CDT(-0500)] <tlev> that would be better than calling the final Log logger = LogFactory.getLog(LOGGER_NAME); each time the method is called

[10:04:33 CDT(-0500)] <tlev> initialize method, not class

[10:11:28 CDT(-0500)] <jgribonvald> ok yes tlev this would be nice to have a better logger initializer

[10:16:18 CDT(-0500)] <jgribonvald> tlev

[10:16:32 CDT(-0500)] <jgribonvald> a such configuration can't be the solution :

[10:16:37 CDT(-0500)] <jgribonvald> <context-param>

[10:16:39 CDT(-0500)] <jgribonvald> <param-name>log4jExposeWebAppRoot</param-name>

[10:16:41 CDT(-0500)] <jgribonvald> <param-value>false</param-value>

[10:16:43 CDT(-0500)] <jgribonvald> </context-param>

[10:18:10 CDT(-0500)] <jgribonvald> ?

[10:38:12 CDT(-0500)] <tlev> well, you would run into the same issue

[10:38:37 CDT(-0500)] <tlev> i was saying that in the DoubleCheckedCreator class just add a method that is "getLogger()"

[10:39:02 CDT(-0500)] <tlev> which on first call would initialize a log

[10:39:12 CDT(-0500)] <tlev> and second call + would use that log

[11:38:26 CDT(-0500)] <jwennmacher> tlev question. I thought that having org.springframework.web.util.WebAppRootListener as the first listener caused the webapp.root key to be initialized before everything else. Is this not the case?

[11:38:49 CDT(-0500)] <jwennmacher> At least that's what we have commented at https://wiki.jasig.org/display/PLT/Logging+Best+Practices

[11:39:26 CDT(-0500)] <tlev> we found that not to be the case, which was odd

[11:39:59 CDT(-0500)] <jwennmacher> meaning this class was not invoked before other listeners?

[11:40:48 CDT(-0500)] <tlev> true

[11:40:49 CDT(-0500)] <jwennmacher> Does the issue manifest for log4j or logback (or both)?

[11:41:02 CDT(-0500)] <tlev> hmmm, i believe logback

[11:42:30 CDT(-0500)] <jwennmacher> If you believe http://stackoverflow.com/questions/178562/how-to-determine-the-order-of-listeners-in-web-xml it states that listeners are called in the order specified in the web.xml

[11:43:55 CDT(-0500)] <tlev> question is, does it happen in serial or in parallel

[11:44:23 CDT(-0500)] <tlev> oh, i just remembered something

[11:46:15 CDT(-0500)] <tlev> nm

[11:47:27 CDT(-0500)] <jwennmacher> Is the logging issue in uPortal (I don't yet see where it is initializing its logging environemtn) or in portlets?

[11:47:36 CDT(-0500)] <jwennmacher> I assume uPortal?

[11:47:51 CDT(-0500)] <tlev> yeah, it was an issue we noticed during uPortal startup

[11:48:17 CDT(-0500)] <tlev> i wish we had taken better notes on it

[11:48:39 CDT(-0500)] <jwennmacher> See http://docs.oracle.com/cd/B14099_19/web.1012/b14017/filters.htm#i1000654, search for 'Event Listener Coding and Deployment Guidelines '. It's not specific enough (at least for me) ...

[11:49:25 CDT(-0500)] <jwennmacher> So uPortal doesn't have the logging initialized the same way the Logging Best Practices states. Do you know how it initializes logging?

[11:50:05 CDT(-0500)] <tlev> depends if you are using the 4.0 logging or 4.1 style logging

[11:50:23 CDT(-0500)] <tlev> we have changed to use logback, but 4.0 is still on log4j

[11:50:51 CDT(-0500)] <tlev> So after briefly looking at the issue, the problem was because in web.xml we have JavaManagementServerListener defined before webAppRootKey

[11:50:56 CDT(-0500)] <tlev> for the context-param

[11:51:19 CDT(-0500)] <tlev> so when the context-param is ran, the class is initialized

[11:51:21 CDT(-0500)] <jwennmacher> It is nice if that's it!

[11:51:47 CDT(-0500)] <tlev> then listeners are ran (which enables the webappRootKey)

[11:52:24 CDT(-0500)] <tlev> so it might only be an issue in 4.1 maybe?

[11:52:58 CDT(-0500)] <tlev> I'll be back online in a bit

[11:53:15 CDT(-0500)] <jwennmacher> ok. I'd like to discuss a bit more when you are back

[12:12:28 CDT(-0500)] <tlev> ok, i'm back

[12:14:38 CDT(-0500)] <jwennmacher> OK and I've researched a bit so I have more intelligent questions (I hope)

[12:15:19 CDT(-0500)] <jwennmacher> I see that in uP 4.1 that we don't use webappRootKey and logback initializes itself, probably upon first instantiation so that explains 4.1

[12:15:30 CDT(-0500)] <jwennmacher> (assuming I am correct)

[12:16:25 CDT(-0500)] <jwennmacher> I looked at rel-4-0-patches and see it is doing the log4J with the log4Log4jConfigListener first.

[12:16:52 CDT(-0500)] <jwennmacher> So in your case you are saying you had another listener before Log4jConfigListener so that's possibly why you had the error?

[12:22:43 CDT(-0500)] <tlev> in the web.xml we had the webapprootkey first

[12:22:59 CDT(-0500)] <tlev> however, we found that there are 2 steps in the initialization process.

[12:23:44 CDT(-0500)] <tlev> After the application starts up and before it services the first request, the servlet container creates and registers an instance of each listener class that you have declared. For each event category, listeners are registered in the order in which they are declared. Then, as the application runs, event listeners for each category are invoked in the order of their registration. All listeners remain active until after the last request

[12:24:58 CDT(-0500)] <tlev> so we noticed during stage 1 (registration) JavaManagementServerListener was trying to init a logger

[12:25:48 CDT(-0500)] <tlev> i believe that was the problem

[12:26:24 CDT(-0500)] <jwennmacher> using log4j, not logback (or does it matter)?

[12:27:39 CDT(-0500)] <tlev> we are using logback

[12:28:17 CDT(-0500)] <tlev> but i'm not sure if that matters

[12:29:11 CDT(-0500)] <jwennmacher> OK so what I think you are saying is that because the logging was initialized in JavaManagementServerListener as a classloading issue, but the logging wasn't initialized until the Log4jConfigListener.contextInitialized(ServletContextEvent) method was invoked, the logging system was not ready during the listener classloading.

[12:29:39 CDT(-0500)] <jwennmacher> I mean the logger was initialized in JavaManagementServerListener as a classloading issue,

[12:31:48 CDT(-0500)] <tlev> i believe that is correct

[12:32:09 CDT(-0500)] <tlev> so we couldn't have logger creation/fetching on the class level, but in a method

[12:32:14 CDT(-0500)] <tlev> shouldn't*

[12:32:18 CDT(-0500)] <tlev> was the end result

[12:32:49 CDT(-0500)] <tlev> so we moved it, but then someone was reporting slowness, which is why i suggested a "caching" type of method that the other method would use

[12:33:16 CDT(-0500)] <jwennmacher> So to circle the wagons ... do you understand why jgribonvald says there is a 1 second delay in login? I didn't get that part.

[12:33:35 CDT(-0500)] <tlev> i was surprised it was that long.

[12:33:48 CDT(-0500)] <tlev> but i guess the lookup for that can take a while?

[12:34:15 CDT(-0500)] <tlev> so the static logger would work, but just have a method which initializes it, instead of class level declaration

[12:38:24 CDT(-0500)] <jwennmacher> I am surprised too. So I think the

[12:38:24 CDT(-0500)] <jwennmacher> <context-param>

[12:38:24 CDT(-0500)] <jwennmacher> <param-name>log4jExposeWebAppRoot</param-name>

[12:38:24 CDT(-0500)] <jwennmacher> <param-value>false</param-value>

[12:38:24 CDT(-0500)] <jwennmacher> </context-param>

[12:38:24 CDT(-0500)] <jwennmacher> change cause logging failures because log4j needs that param set? Would it make sense to simply substitute the logfile path into the log4j.properties file during the build process like 4.1 does? Then log4j will initialize itself upon first use.

[12:39:08 CDT(-0500)] <tlev> we could do that

[12:41:49 CDT(-0500)] <jwennmacher> Hmm.... I stand corrected. I just looked at the latest rel-4-0-patches and I see it already has log4jExposeWebAppRoot=false and log4j.properties doesn't use the webAppRootKey at all. Problem already solved???

[12:43:20 CDT(-0500)] <jwennmacher> Haha. I was the one who made the log4j.properties change back on 10/1/12. My memory is so short lived ...

[12:44:22 CDT(-0500)] <tlev> that'll happen

[12:45:05 CDT(-0500)] <jwennmacher> And the log4jExposeWebAppRoot=false in web.xml was from 5/25/07. So if the code was already like this, I'm a bit confused. If I understand from our discussion logging should have been able to self initialize on class loading.

[12:45:45 CDT(-0500)] <tlev> UW's config is a bit different

[12:45:54 CDT(-0500)] <jwennmacher> Did your version use the WebAppRootKey?

[12:46:00 CDT(-0500)] * tlev checking

[12:46:35 CDT(-0500)] <tlev> but i believe we are

[12:47:57 CDT(-0500)] <jwennmacher> So I believe if everyone switched to have the log file dir substituted at build (and could leave the log4jExposeWebAppRoot=false in their web.xml) then the logging could be initialized at class load time (if I understand correctly).

[12:48:55 CDT(-0500)] <tlev> i believe so, however shouldn't we still avoid doing so where we can just in case there is an issue. at least with listener classes

[12:49:54 CDT(-0500)] <jwennmacher> Sounds reasonable. I suggest adding a bit of documentation since that is not the norm throughout the code and it is not obvious why it was done (at least to me)

[12:50:14 CDT(-0500)] <tlev> sure, do we have a place on the wiki this would be best for?

[12:52:44 CDT(-0500)] <jwennmacher> The uPortal manual Logging Best Practices would be the place. https://wiki.jasig.org/display/UPM40/Logging+Best+Practices. Maybe mention it in the portlet Logging Best Practices too at https://wiki.jasig.org/display/PLT/Logging+Best+Practices

[12:53:08 CDT(-0500)] <jwennmacher> I was thinking in the code in the specific Listener classes near the log init method

[12:53:28 CDT(-0500)] <jwennmacher> I hadn't thought of the wiki pages, but I'm glad you did!

[12:53:33 CDT(-0500)] <tlev> ok, i shall add it in

[12:53:48 CDT(-0500)] <jwennmacher> cool. Thanks.