uPortal IRC Logs-2010-07-08

[08:54:58 CDT(-0500)] * EricDalquist (~dalquist@2607:f388:e:0:221:9bff:fe37:e768) has joined ##uportal
[09:25:41 CDT(-0500)] * lfuller (~sparhk@wsip-72-215-204-133.ph.ph.cox.net) has joined ##uportal
[09:55:26 CDT(-0500)] * bsparks (~bsparks@wsip-72-215-204-133.ph.ph.cox.net) has joined ##uportal
[10:29:12 CDT(-0500)] * awills (~awills@wsip-72-215-204-133.ph.ph.cox.net) has joined ##uportal
[10:42:43 CDT(-0500)] * JoeMoore (89d88117@gateway/web/freenode/ip.137.216.129.23) has joined ##uportal
[11:27:51 CDT(-0500)] * mccordl (~mccordl@slc-120-7.southwestern.edu) has joined ##uportal
[11:31:58 CDT(-0500)] <awills> I'm getting a lot of the following when i run initdb/initportal with db stats turned on in trunk/: http://uportal.pastebin.com/37Za3v6k
[11:32:10 CDT(-0500)] <awills> doesn't seeem to happen with 3.2
[11:32:32 CDT(-0500)] <EricDalquist> its a race condition
[11:32:36 CDT(-0500)] <EricDalquist> stats are generated and queued
[11:32:42 CDT(-0500)] <EricDalquist> but the context gets shut down before the flush
[11:33:25 CDT(-0500)] <awills> that's what it looked like... is there an elegant adjustment we could make to overcome it?
[11:33:42 CDT(-0500)] <EricDalquist> not really :/
[11:33:50 CDT(-0500)] <EricDalquist> I think flush gets called on shutdown already
[11:33:55 CDT(-0500)] <awills> i'm not sure why the scheduler operations aren't keeping the context open
[11:34:03 CDT(-0500)] <EricDalquist> but if the JPA context gets closed first it fails
[11:34:09 CDT(-0500)] <EricDalquist> well it waits for them to complete
[11:34:19 CDT(-0500)] <EricDalquist> but there are not guarantees about bean shutdown order
[11:34:40 CDT(-0500)] <EricDalquist> so if the JPA or DataSource beans get shut down first then stuff that uses them will fail
[11:34:51 CDT(-0500)] <awills> what causes the spring context to close? are we explicitly doing that somewhere?
[11:35:02 CDT(-0500)] <EricDalquist> the crn script completing
[11:35:22 CDT(-0500)] <EricDalquist> its the last operation
[11:36:52 CDT(-0500)] <awills> but it's implicit, right? we're nowhere call a method to shut it down explicitly
[11:37:02 CDT(-0500)] <EricDalquist> we might
[11:37:04 CDT(-0500)] <EricDalquist> I don't know
[11:37:23 CDT(-0500)] <EricDalquist> I think uPortal registers a JVM shutdown hook for an app context loaded via a command line tool
[11:37:28 CDT(-0500)] <EricDalquist> so that is a potential source
[11:37:42 CDT(-0500)] <EricDalquist> we may be calling context.close() in the import/export scripts too
[11:38:42 CDT(-0500)] <awills> was just looking for that... don't see it, fwiw
[11:39:40 CDT(-0500)] <EricDalquist> so anything that loads the app context fromPortalApplicationContextLocator should be calling the shutdown() method there when it is done with it
[11:39:40 CDT(-0500)] <EricDalquist> but
[11:40:08 CDT(-0500)] <EricDalquist> that class also does "genericApplicationContext.registerShutdownHook();"
[11:40:19 CDT(-0500)] <EricDalquist> after creating the context for a command line app
[11:40:31 CDT(-0500)] <EricDalquist> just to be sure things actually get shut down
[11:42:24 CDT(-0500)] <awills> carFilesLoadingTrigger, cacheMaintenanceTrigger, dlmFragmentCleanerTrigger, statsQueueFlushingTrigger...
[11:42:44 CDT(-0500)] <awills> are any of those important for command-line operations?
[11:42:55 CDT(-0500)] <EricDalquist> probably not
[11:43:20 CDT(-0500)] <EricDalquist> though without statsQueueFlushingTrigger no stats will be written to the DB
[11:43:26 CDT(-0500)] <awills> we could send a system property that signals the uPortalTaskScheduler to lay off
[11:43:30 CDT(-0500)] <EricDalquist> and then you're guaranteed to get that error are message
[11:43:40 CDT(-0500)] <awills> hmm
[11:44:02 CDT(-0500)] <EricDalquist> QueueingEventHandler implements DisposableBean
[11:44:17 CDT(-0500)] <EricDalquist> which does
[11:44:17 CDT(-0500)] <EricDalquist> flush
[11:44:35 CDT(-0500)] <EricDalquist> you could look at adding a parameter to QueueingEventHandler.flush()
[11:44:43 CDT(-0500)] <EricDalquist> a "boolean disposing"
[11:44:56 CDT(-0500)] <EricDalquist> and turn down the logging if there is an error during dispose
[11:45:01 CDT(-0500)] <EricDalquist> versus a normal flush call
[11:45:18 CDT(-0500)] <EricDalquist> you'd need to leave a non-parameterized flush() method there not to break existing code
[11:45:22 CDT(-0500)] <EricDalquist> but it could just call the new one
[11:46:55 CDT(-0500)] <awills> what about clling SchedulerFactoryBean.stop() explicitly somewhere?
[11:47:28 CDT(-0500)] <EricDalquist> where?
[11:47:44 CDT(-0500)] <awills> checking
[11:47:46 CDT(-0500)] <EricDalquist> we don't know shutdown is happening until its too late
[11:53:23 CDT(-0500)] <awills> something like this (haven't tried it yet): http://uportal.pastebin.com/vAY5hzs5
[11:54:00 CDT(-0500)] <EricDalquist> that could work
[11:54:11 CDT(-0500)] <awills> running it now, just a sec
[11:54:22 CDT(-0500)] <EricDalquist> you'd have to add a call to shutdown in a finally() in all the crn wrapper scripts too
[11:55:29 CDT(-0500)] <awills> come again?
[11:55:47 CDT(-0500)] <EricDalquist> so nothing in the crn scripts is currently calling that shutdown method
[11:56:13 CDT(-0500)] <EricDalquist> loading the spring context in the portal app context locator makes spring register its own shutdown hook
[11:56:24 CDT(-0500)] <EricDalquist> which is getting called when the JVM is exiting
[12:00:48 CDT(-0500)]

[12:00:58 CDT(-0500)] <EricDalquist> yes
[12:01:06 CDT(-0500)] <EricDalquist> and that creates a new spring app context
[12:01:28 CDT(-0500)] <EricDalquist> and calls http://static.springsource.org/spring/docs/2.5.x/api/org/springframework/context/support/AbstractApplicationContext.html#registerShutdownHook()
[12:01:32 CDT(-0500)] <EricDalquist> on that new context
[12:01:57 CDT(-0500)] <EricDalquist> unless the scripts are also calling org.jasig.portal.spring.PortalApplicationContextLocator.shutdown() the shutdown method in PortalApplicationContextLocator never runs
[12:02:16 CDT(-0500)] <awills> hmmm... ok
[12:02:30 CDT(-0500)] <EricDalquist> Spring's shutdown hook runs with the JVM shutsdown if something hasn't already called close() on the context
[12:02:50 CDT(-0500)]

<EricDalquist> so for your change to work the CRN scripts have to always finish by calling $

Unknown macro: {groovy(org.jasig.portal.spring.PortalApplicationContextLocator.shutdown())}

[12:03:46 CDT(-0500)] <awills> registerShutdownHook() should take a callback
[12:04:30 CDT(-0500)] <awills> that's probably worth doing (calling ContextLocator.shutdown()) anyway
[12:04:36 CDT(-0500)] <EricDalquist> except it doesn't
[12:04:47 CDT(-0500)] <awills> i can see that
[12:05:20 CDT(-0500)] <EricDalquist> is it hard to add a finally block to the crn scripts to do the shutdown call?
[12:14:18 CDT(-0500)] <awills> shouldn't be... i'm on it
[12:37:18 CDT(-0500)] <awills> none of this is working
[12:37:30 CDT(-0500)] <awills> the events in the queue are still unflushed
[12:38:08 CDT(-0500)] <EricDalquist> so the problem is this ordering:
[12:40:27 CDT(-0500)] <EricDalquist> scheduler calls queue.flush
[12:40:27 CDT(-0500)] <EricDalquist> stuff happens that adds events to queue
[12:40:27 CDT(-0500)] <EricDalquist> scheduler.shutdown
[12:40:27 CDT(-0500)] <EricDalquist> context.shutdown
[12:40:27 CDT(-0500)] <EricDalquist> jpa beans shutdown
[12:40:28 CDT(-0500)] <EricDalquist> queue.dispose gets called and there are still events
[12:40:45 CDT(-0500)] <EricDalquist> since there wasn't a scheudler queue.flush call in progress it shuts down right away
[12:41:32 CDT(-0500)] <EricDalquist> that's why I was suggesting modifying the queue so that the flush knows it was called by dispose()
[12:41:47 CDT(-0500)] <EricDalquist> and doesn't make as much noise in the logs about events still being in the queue
[12:42:06 CDT(-0500)] <awills> ah... that's interesting
[12:43:19 CDT(-0500)] <awills> yes, i suppose it's only logging info we're looking at... not exceptions "bubling up" from the stats tech
[12:45:49 CDT(-0500)] <EricDalquist> yeah
[12:52:23 CDT(-0500)] <awills> decent?: http://uportal.pastebin.com/aGsx7hz8
[12:52:40 CDT(-0500)] <EricDalquist> that works too
[12:52:49 CDT(-0500)] <awills> going to add a comment to that
[12:55:21 CDT(-0500)] <awills> ok, so much for the easy issue... now the other loose end: http://uportal.pastebin.com/Ahh70rPx
[12:55:36 CDT(-0500)] <awills> there's a whole different JPA setup for stats
[12:56:13 CDT(-0500)] <EricDalquist> well for one we're not using Autowiring in uPortal until trunk
[12:56:30 CDT(-0500)] <EricDalquist> so just remove the @Autowired and wire in the TX manager for the DB the locks are stored in
[12:56:37 CDT(-0500)] <EricDalquist> which would be the main one
[12:57:55 CDT(-0500)] * colinclark (~colin@bas2-toronto09-1176131686.dsl.bell.ca) has joined ##uportal
[12:58:10 CDT(-0500)] <awills> is it ok if the lock is in one ORM context, but the rest of the transaction occurs in another?
[12:58:49 CDT(-0500)] <EricDalquist> yeah
[12:58:58 CDT(-0500)] <EricDalquist> I think so ...
[12:59:16 CDT(-0500)] <EricDalquist> it may have to hold a TX open for both contexts
[13:00:20 CDT(-0500)] <awills> k
[13:00:30 CDT(-0500)] * mccordl (~mccordl@slc-120-7.southwestern.edu) has joined ##uportal
[13:09:59 CDT(-0500)] <awills> perhaps this isn't as vexing as i thought... confused myself at the end of the day yesterday... went home thinking the issue was with the autowiring of @PersistenceContext setEntityManager
[13:33:56 CDT(-0500)] * mccordl (~mccordl@slc-120-7.southwestern.edu) has left ##uportal
[13:49:09 CDT(-0500)] * JoeMoore_ (89d81409@gateway/web/freenode/ip.137.216.20.9) has joined ##uportal
[13:53:23 CDT(-0500)] * JoeMoore2 (89d81084@gateway/web/freenode/ip.137.216.16.132) has joined ##uportal
[16:30:57 CDT(-0500)] <awills> EricDalquist – the cascade feature doesn't appear to be available in HQL at present: http://opensource.atlassian.com/projects/hibernate/browse/HHH-695
[18:02:08 CDT(-0500)] * bsparks (~bsparks@wsip-72-215-204-133.ph.ph.cox.net) has joined ##uportal
[20:16:11 CDT(-0500)] * awills1 (~awills@ip68-3-30-21.ph.ph.cox.net) has joined ##uportal
[20:16:29 CDT(-0500)] * awills1 (~awills@ip68-3-30-21.ph.ph.cox.net) has left ##uportal
[20:46:57 CDT(-0500)] * lfuller (~sparhk@ip68-98-56-21.ph.ph.cox.net) has joined ##uportal