Okay, I saw with my own two eyes (and you can see the time difference) that
there was a time delay between 1st call to @PreDestroy and 2nd call to
@PreDestroy. See below.
LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
LoginFilter.doFilter(): session = NOT null
LoginFilter.doFilter(): pf_usersController = NOT null
LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/pf_viewExpired.jsf
LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
pf_UsersController.sessionTimeout(): administrator session ended at Fri Dec
07 04:31:48 EST 2012
*------ HUGE time delay right here at this point ---------*
Dec 07, 2012 4:33:38 AM org.apache.openejb.cdi.CdiAppContextsService
lazyStartSessionContext
WARNING: Could NOT lazily initialize session context because of null
RequestContext
pf_UsersController.sessionTimeout(): user == null || userName == null;
@PreDestroy sessionTimeout invoked 2nd time
On Fri, Dec 7, 2012 at 4:30 AM, Howard W. Smith, Jr. <smithh032...@gmail.com
> wrote:
>
> Below, copied from catalina log file (to show date/time when app completed
> 'start' and when accessed login page)
>
> Dec 07, 2012 4:11:02 AM org.apache.catalina.startup.Catalina start
> INFO: Server startup in 22788 ms
> Dec 07, 2012 4:14:44 AM org.apache.myfaces.el.unified.ResolverBuilderBase
> sortELResolvers
> INFO: Chain of EL resolvers for Faces sorted with:
> org.apache.myfaces.el.unified.OpenWebBeansELResolverComparator@1b14920fand
> the result order is
> [org.apache.myfaces.el.unified.resolver.implicitobject.ImplicitObjectResolver@638124ac,
> org.apache.myfaces.el.unified.resolver.CompositeComponentELResolver@338ecb3d,
> org.apache.myfaces.el.FlashELResolver@63c12c3c,
> org.apache.myfaces.el.unified.resolver.ManagedBeanResolver@1f3f4a4e,
> org.apache.myfaces.el.unified.resolver.ResourceResolver@742756e8,
> javax.el.ResourceBundleELResolver@42bad4eb,
> org.apache.myfaces.el.unified.resolver.ResourceBundleResolver@77f0b286,
> javax.el.MapELResolver@5b58b8ee, javax.el.ListELResolver@1dd5401c,
> javax.el.ArrayELResolver@1b63fd91, javax.el.BeanELResolver@419c48a3,
> org.apache.webbeans.el.WebBeansELResolver@7b64e6fb]
>
> Below, copied from NetBeans output pane (these were swallowed and not in
> catalina log file)
>
> Dec 07, 2012 4:11:02 AM org.apache.catalina.startup.Catalina start
> INFO: Server startup in 22788 ms
> LoginFilter.doFilter(): session = NOT null
> LoginFilter.doFilter(): pf_usersController = NOT null
> LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/login.jsf
> LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
> LoginFilter.doFilter(): agent.getUserAgent() = mozilla/5.0 (windows nt
> 6.0; wow64) applewebkit/537.11 (khtml, like gecko) chrome/23.0.1271.95
> safari/537.11
> Dec 07, 2012 4:14:44 AM org.apache.myfaces.el.unified.ResolverBuilderBase
> sortELResolvers
> INFO: Chain of EL resolvers for Faces sorted with:
> org.apache.myfaces.el.unified.OpenWebBeansELResolverComparator@1b14920fand
> the result order is
> [org.apache.myfaces.el.unified.resolver.implicitobject.ImplicitObjectResolver@638124ac,
> org.apache.myfaces.el.unified.resolver.CompositeComponentELResolver@338ecb3d,
> org.apache.myfaces.el.FlashELResolver@63c12c3c,
> org.apache.myfaces.el.unified.resolver.ManagedBeanResolver@1f3f4a4e,
> org.apache.myfaces.el.unified.resolver.ResourceResolver@742756e8,
> javax.el.ResourceBundleELResolver@42bad4eb,
> org.apache.myfaces.el.unified.resolver.ResourceBundleResolver@77f0b286,
> javax.el.MapELResolver@5b58b8ee, javax.el.ListELResolver@1dd5401c,
> javax.el.ArrayELResolver@1b63fd91, javax.el.BeanELResolver@419c48a3,
> org.apache.webbeans.el.WebBeansELResolver@7b64e6fb]
> LoginFilter.doFilter(): session = NOT null
> LoginFilter.doFilter(): pf_usersController = NOT null
> LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/login.jsf
> LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
> [EL Info]: 2012-12-07
> 04:14:46.223--ServerSession(1630457336)--EclipseLink, version: Eclipse
> Persistence Services - 2.3.2.v20111125-r10461
> [EL Info]: 2012-12-07
> 04:14:46.784--ServerSession(1630457336)--file:/C:/apache-tomee-plus-1.5.1-SNAPSHOT/webapps/mcmsweb/WEB-INF/classes/_mcmsPU
> login successful
> GoogleCalendarUtil: calendarList.getEntries().size() = 2
> GoogleCalendarUtil: calendar ID/summary = oleta...@gmail.com/mcmsweb
> GoogleCalendarUtil: calendar ID/summary =
> 998449989...@developer.gserviceaccount.com/998449989...@developer.gserviceaccount.com
> GoogleCalendarUtil: events.getItems().size() = 250
> pf_UsersController.loginUser(): administrator logged in at Fri Dec 07
> 04:14:47 EST 2012
> LoginFilter.doFilter(): session = NOT null
> LoginFilter.doFilter(): pf_usersController = NOT null
> LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/index.jsf
> LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
> LoginFilter.doFilter(): session = NOT null
> LoginFilter.doFilter(): pf_usersController = NOT null
> LoginFilter.doFilter(): req.getRequestURI() =
> /mcmsweb/javax.faces.resource/images/ui-bg_flat_0_2d5972_40x100.png.jsf
> LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
> LoginFilter.doFilter(): session = NOT null
> LoginFilter.doFilter(): pf_usersController = NOT null
> LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/pf_viewExpired.jsf
> LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
> pf_UsersController.sessionTimeout(): administrator session ended at Fri
> Dec 07 04:16:15 EST 2012
> pf_UsersController.sessionTimeout(): user == null || userName == null;
> @PreDestroy sessionTimeout invoked 2nd time
> Dec 07, 2012 4:18:06 AM org.apache.openejb.cdi.CdiAppContextsService
> lazyStartSessionContext
> WARNING: Could NOT lazily initialize session context because of null
> RequestContext
> ApplicationScopeBean.destroy() invoked
>
>
> Below, copied from catalina log file (to show date/time after session
> timeout and app undeployed from TomEE; 2-minute delay between session
> timeout and lazystartsessioncontext; don't know why)
>
> Dec 07, 2012 4:18:06 AM org.apache.openejb.cdi.CdiAppContextsService
> lazyStartSessionContext
> WARNING: Could NOT lazily initialize session context because of null
> RequestContext
> Dec 07, 2012 4:19:37 AM org.apache.openejb.assembler.classic.Assembler
> destroyApplication
> INFO: Undeploying app: C:\apache-tomee-plus-1.5.1-SNAPSHOT\webapps\mcmsweb
> Dec 07, 2012 4:19:39 AM org.apache.catalina.loader.WebappClassLoader
> checkThreadLocalMapForLeaks
> SEVERE: The web application [/mcmsweb] created a ThreadLocal with key of
> type [com.google.api.client.util.escape.Platform$1] (value
> [com.google.api.client.util.escape.Platform$1@7ec4f311]) and a value of
> type [char[]] (value [[C@3432221c]) but failed to remove it when the web
> application was stopped. Threads are going to be renewed over time to try
> and avoid a probable memory leak.
> Dec 07, 2012 4:19:39 AM org.apache.catalina.loader.WebappClassLoader
> checkThreadLocalMapForLeaks
> SEVERE: The web application [/mcmsweb] created a ThreadLocal with key of
> type [com.google.gson.Gson$1] (value [com.google.gson.Gson$1@475d7709])
> and a value of type [java.util.HashMap] (value [{}]) but failed to remove
> it when the web application was stopped. Threads are going to be renewed
> over time to try and avoid a probable memory leak.
> Dec 07, 2012 4:19:40 AM org.apache.catalina.startup.HostConfig
> deleteRedeployResources
> INFO: Undeploying context [/mcmsweb]
>
>
>
>
> On Fri, Dec 7, 2012 at 4:09 AM, Romain Manni-Bucau
> <rmannibu...@gmail.com>wrote:
>
>> well this method is only called when a bean in this scope is called
>> (maybe after your filter)
>>
>> Romain Manni-Bucau
>> Twitter: @rmannibucau
>> Blog: http://rmannibucau.wordpress.com/
>> LinkedIn: http://fr.linkedin.com/in/rmannibucau
>> Github: https://github.com/rmannibucau
>>
>>
>>
>> 2012/12/7 Howard W. Smith, Jr. <smithh032...@gmail.com>:
>> > To confirm what i mentioned in previous email below (my loginfilter
>> should
>> > not be responsible for 2 calls to @PreDestroy). See server log below.
>> You
>> > might want to look at the code in
>> org.apache.openejb.cdi.CdiAppContextsService
>> > lazyStartSessionContext, and see why this is called or at what point is
>> > this called by container or in lifecycle. Look for next email, have an
>> > idea, something else to add to the log. :)
>> >
>> > INFO: Server startup in 27176 ms
>> > LoginFilter.doFilter(): session = NOT null
>> > LoginFilter.doFilter(): pf_usersController = NOT null
>> > LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/login.jsf
>> > LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
>> > LoginFilter.doFilter(): agent.getUserAgent() = mozilla/5.0 (windows nt
>> 6.0;
>> > wow64) applewebkit/537.11 (khtml, like gecko) chrome/23.0.1271.95
>> > safari/537.11
>> > Dec 07, 2012 3:54:55 AM
>> org.apache.myfaces.el.unified.ResolverBuilderBase
>> > sortELResolvers
>> > INFO: Chain of EL resolvers for Faces sorted with:
>> > org.apache.myfaces.el.unified.OpenWebBeansELResolverComparator@1e233895and
>> > the result order is
>> >
>> [org.apache.myfaces.el.unified.resolver.implicitobject.ImplicitObjectResolver@1a57cda8
>> ,
>> >
>> org.apache.myfaces.el.unified.resolver.CompositeComponentELResolver@7a7ede1a
>> ,
>> > org.apache.myfaces.el.FlashELResolver@1f27bbca,
>> > org.apache.myfaces.el.unified.resolver.ManagedBeanResolver@6999dac0,
>> > org.apache.myfaces.el.unified.resolver.ResourceResolver@73e8a969,
>> > javax.el.ResourceBundleELResolver@2fca67f2,
>> > org.apache.myfaces.el.unified.resolver.ResourceBundleResolver@116e5961,
>> > javax.el.MapELResolver@63adf837, javax.el.ListELResolver@32831601,
>> > javax.el.ArrayELResolver@3c19b58f, javax.el.BeanELResolver@3bdede1c,
>> > org.apache.webbeans.el.WebBeansELResolver@24c81ef9]
>> > LoginFilter.doFilter(): session = NOT null
>> > LoginFilter.doFilter(): pf_usersController = NOT null
>> > LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/login.jsf
>> > LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
>> > [EL Info]: 2012-12-07
>> 03:55:03.682--ServerSession(1877145955)--EclipseLink,
>> > version: Eclipse Persistence Services - 2.3.2.v20111125-r10461
>> > [EL Info]: 2012-12-07
>> >
>> 03:55:04.262--ServerSession(1877145955)--file:/C:/apache-tomee-plus-1.5.1-SNAPSHOT/webapps/mcmsweb/WEB-INF/classes/_mcmsPU
>> > login successful
>> > GoogleCalendarUtil: calendarList.getEntries().size() = 2
>> > GoogleCalendarUtil: calendar ID/summary = oleta...@gmail.com/mcmsweb
>> > GoogleCalendarUtil: calendar ID/summary =
>> >
>> 998449989...@developer.gserviceaccount.com/998449989...@developer.gserviceaccount.com
>> > GoogleCalendarUtil: events.getItems().size() = 250
>> > pf_UsersController.loginUser(): brian logged in at Fri Dec 07 03:55:04
>> EST
>> > 2012
>> > LoginFilter.doFilter(): session = NOT null
>> > LoginFilter.doFilter(): pf_usersController = NOT null
>> > LoginFilter.doFilter(): req.getRequestURI() = /mcmsweb/index.jsf
>> > LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
>> > LoginFilter.doFilter(): session = NOT null
>> > LoginFilter.doFilter(): pf_usersController = NOT null
>> > LoginFilter.doFilter(): req.getRequestURI() =
>> >
>> /mcmsweb/javax.faces.resource/images/ui-bg_white-lines_85_f7f7ba_40x100.png.jsf
>> > LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
>> > LoginFilter.doFilter(): session = NOT null
>> > LoginFilter.doFilter(): pf_usersController = NOT null
>> > LoginFilter.doFilter(): req.getRequestURI() =
>> /mcmsweb/pf_viewExpired.jsf
>> > LoginFilter.doFilter(): ajaxRequest = false; ajaxHeader = null
>> > pf_UsersController.sessionTimeout(): brian session ended at Fri Dec 07
>> > 03:56:23 EST 2012
>> > Dec 07, 2012 3:58:08 AM org.apache.openejb.cdi.CdiAppContextsService
>> > lazyStartSessionContext
>> > WARNING: Could NOT lazily initialize session context because of null
>> > RequestContext
>> >
>> >
>> >
>> >
>> > On Fri, Dec 7, 2012 at 3:33 AM, Howard W. Smith, Jr. <
>> smithh032...@gmail.com
>> >> wrote:
>> >
>> >> Honestly, i 'do' have a servlet filter in place that @Inject
>> >> pf_UserController, but please note/remember... session timed out due to
>> >> session timeout value in web.xml, @PreDestroy is invoked, and then
>> >> @PreDestroy is invoked again... no other code is called in between.
>> >>
>> >> I really don't think my servlet filter (login filter) is responsible
>> for
>> >> @PreDestroy being called a 2nd time.
>> >>
>> >> let me turn on debug = true in my login/servlet filter and see what
>> >> happens between 1st and 2nd call to @PreDestroy.
>> >>
>> >>
>>
>
>
