uPortal IRC Logs-2012-05-25

Owned by Apereo Infrastructure
Last updated: May 25, 2012
5 min read

[13:24:50 CDT(-0500)] <athena1> hey EricDalquist are you around?

[13:24:55 CDT(-0500)] <EricDalquist> yup

[13:25:00 CDT(-0500)] <athena1> i'm now getting "Caused by: java.lang.IllegalArgumentException: interface org.hibernate.engine.jdbc.ClobImplementer is not visible from class loader"

[13:25:06 CDT(-0500)] <athena1> specifically on postgres

[13:25:11 CDT(-0500)] <EricDalquist> hrm

[13:25:15 CDT(-0500)] <EricDalquist> can you share a full stack trace?

[13:25:19 CDT(-0500)] <athena1> yeah

[13:25:30 CDT(-0500)] <athena1> preventing the news reader portlet from working for authed users

[13:25:41 CDT(-0500)] <EricDalquist> does NRP use hibernate at all?

[13:27:04 CDT(-0500)] <athena1> http://pastebin.com/UWJvGPgy

[13:27:08 CDT(-0500)] <athena1> yes, but i'm not sure ti's the NRP

[13:27:45 CDT(-0500)] <athena1> hm.

[13:27:54 CDT(-0500)] <EricDalquist> what is the error line in the log for this?

[13:27:56 CDT(-0500)] <athena1> i don't think it uses JPA, which is what's showing up in the stack trace

[13:27:59 CDT(-0500)] <EricDalquist> does it include the portlet's fname?

[13:28:05 CDT(-0500)] <EricDalquist> well right the portal uses JPA

[13:28:22 CDT(-0500)] <athena1> WARN [TP-Processor1] May/25 11:24:30,311 worker.PortletResourceExecutionWorker.[] - Execution failed on portlet window

[13:28:22 CDT(-0500)] <athena1> 46_u32l1n8_35.tw

[13:28:22 CDT(-0500)] <athena1> java.util.concurrent.ExecutionException: org.jasig.portal.portlet.PortletDispatchException: The portlet window 'PortletW

[13:28:22 CDT(-0500)] <athena1> indow [portletWindowId=46_u32l1n8_35.tw, delegationParentId=null, portletMode=view, windowState=detached, expirationCach

[13:28:22 CDT(-0500)] <athena1> e=null, renderParameters={}, publicRenderParameters={}, portletEntity=PortletEntity [portletEntityId=46_u32l1n8_35, layo

[13:28:23 CDT(-0500)] <athena1> utNodeId=u32l1n8, userId=35, portletDefinition=PortletDefinition [portletDefinitionId=46, fname=news, portletDescriptorK

[13:28:23 CDT(-0500)] <athena1> ey=PortletDescriptorKey [frameworkPortlet=false, webAppName=/NewsReaderPortlet, portletName=news], portletType=PortletTy

[13:28:24 CDT(-0500)] <athena1> peImpl [internalId=1, name=Portlet, descr=Adapter for JSR-168 and JSR-286 Portlets, cpdUri=/org/jasig/portal/portlets/Ge

[13:28:24 CDT(-0500)] <athena1> nericPortlet.cpd.xml]]]]' threw an exception while executing serveResource.

[13:28:32 CDT(-0500)] <EricDalquist> huh

[13:28:37 CDT(-0500)] <EricDalquist> so this is in a tomcat thread

[13:28:40 CDT(-0500)] <EricDalquist> not a portlet execution thread

[13:29:20 CDT(-0500)] <athena1> herewe go - the very first part of the error:

[13:29:20 CDT(-0500)] <athena1> WARN [uPortal-PortletExecutor-4-RESOURCE-[news]] May/25 11:24:30,309 worker.PortletResourceExecutionWorker.[] - Portlet '46_u32l1n8_35.tw' failed with an exception

[13:29:20 CDT(-0500)] <athena1> org.jasig.portal.portlet.PortletDispatchException: The portlet window 'PortletWindow [portletWindowId=46_u32l1n8_35.tw, delegationParentId=null, portletMode=view, windowState=detached, expirationCache=null, renderParameters={}, publicRenderParameters={}, portletEntity=PortletEntity [portletEntityId=46_u32l1n8_35, layoutNodeId=u32l1n8, userId=35, portletDefinition=PortletDefinition [portletDefinitionId=46, fname=news, portletDescrip

[13:29:32 CDT(-0500)] <EricDalquist> ok

[13:29:39 CDT(-0500)] <EricDalquist> so it is the news reader portlet

[13:29:42 CDT(-0500)] <athena1> there's a really long mess of stack traces

[13:29:46 CDT(-0500)] <EricDalquist> yeah

[13:29:58 CDT(-0500)] <athena1> huh.

[13:29:59 CDT(-0500)] <EricDalquist> it looks like that pastebin is actually two traces together

[13:30:07 CDT(-0500)] <EricDalquist> is this coming from a terminal?

[13:30:23 CDT(-0500)] <athena1> yeah

[13:30:45 CDT(-0500)] <athena1> ok, this does look like it's related to portlet preferences persistence, which is what i was worried about

[13:31:05 CDT(-0500)] <EricDalquist> yeah

[13:31:06 CDT(-0500)] <athena1> http://pastebin.com/Mb4DPAHU

[13:31:08 CDT(-0500)] <EricDalquist> I'm sure that is it

[13:31:31 CDT(-0500)] <EricDalquist> ahh

[13:31:37 CDT(-0500)] <EricDalquist> you are using the most recent code in master right?

[13:31:42 CDT(-0500)] <athena1> yes

[13:31:45 CDT(-0500)] <EricDalquist> ok

[13:31:58 CDT(-0500)] <athena1> saw there were some changes that looked like they might be persistence-related

[13:31:59 CDT(-0500)] <EricDalquist> so the recent portlet prefs refactoring (to address that calendar portlet perf error) missed a step

[13:32:14 CDT(-0500)] <EricDalquist> the classloader switching aspect is not being applied to the new solution

[13:32:37 CDT(-0500)] <athena1> ah

[13:32:41 CDT(-0500)] <EricDalquist> what should happen when a portlet calls back to the portal is an aspect should switch the classloader back to the portal's

[13:32:45 CDT(-0500)] <EricDalquist> that isn't happening

[13:33:20 CDT(-0500)] <athena1> ok

[13:33:25 CDT(-0500)] <athena1> how hard will this be to fix?

[13:33:33 CDT(-0500)] <EricDalquist> not too hard

[13:35:04 CDT(-0500)] <athena1> ok

[13:35:48 CDT(-0500)] <athena1> came up while testing the conference app for submission

[13:36:05 CDT(-0500)] <EricDalquist> so in short

[13:36:44 CDT(-0500)] <EricDalquist> we need to apply ThreadContextClassLoaderAspect as an aspect to the PortletPreferences objects created by PortletEnvironmentServiceImpl.createPortletPreferences

[13:40:12 CDT(-0500)] <athena1> ok

[13:40:24 CDT(-0500)] <EricDalquist> I should have something for you to try in ~ 5 minutes

[13:40:32 CDT(-0500)] <athena1> thanks so much

[13:40:51 CDT(-0500)] <athena1> i have to admit i'm still not totally over being sick

[13:40:59 CDT(-0500)] <EricDalquist> no problem

[13:49:33 CDT(-0500)] <EricDalquist> athena1: https://github.com/Jasig/uPortal/commit/4727100ad4614fc5869c8ff8fe08cc7431f2dbfd

[13:49:36 CDT(-0500)] <EricDalquist> that isn't on master yet

[13:49:41 CDT(-0500)] <EricDalquist> it is on a working branch

[13:49:44 CDT(-0500)] <EricDalquist> but can you give that a try?

[13:49:48 CDT(-0500)] <EricDalquist> I have to run and get lunch

[13:49:58 CDT(-0500)] <EricDalquist> but I'll be back in ~30 minutes

[13:50:49 CDT(-0500)] <athena1> will try, thanks

[14:03:27 CDT(-0500)] <athena1> hm.

[14:03:28 CDT(-0500)] <athena1> [java] ... 53 more

[14:03:28 CDT(-0500)] <athena1> [java] Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name '(inner bean)': Initialization of bean failed; nested exception is java.lang.IllegalArgumentException: Unable to locate method [doThreadContextClassLoaderUpdate] on bean [threadContextClassLoaderAspect]

[14:03:28 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:527)

[14:03:28 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)

[14:03:28 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveInnerBean(BeanDefinitionValueResolver.java:270)

[14:03:29 CDT(-0500)] <athena1> [java] ... 61 more

[14:03:29 CDT(-0500)] <athena1> [java] Caused by: java.lang.IllegalArgumentException: Unable to locate method [doThreadContextClassLoaderUpdate] on bean [threadContextClassLoaderAspect]

[14:03:30 CDT(-0500)] <athena1> [java] at org.springframework.aop.config.MethodLocatingFactoryBean.setBeanFactory(MethodLocatingFactoryBean.java:75)

[14:03:30 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeAwareMethods(AbstractAutowireCapableBeanFactory.java:1475)

[14:03:31 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1443)

[14:03:31 CDT(-0500)] <athena1> [java] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)

[14:03:32 CDT(-0500)] <athena1> [java] ... 63 more

[14:03:36 CDT(-0500)] <athena1> err, sorry, that was sort of bigger than i thought

[14:09:10 CDT(-0500)] <EricDalquist> back

[14:09:19 CDT(-0500)] <EricDalquist> oh ,... can you gist/pastbin that?

[14:10:58 CDT(-0500)] <athena1> http://pastebin.com/EvJgm0MP

[14:11:58 CDT(-0500)] <EricDalquist> ah ok ... go into persistenceContext.xml

[14:12:14 CDT(-0500)] <EricDalquist> replace all occurances of "doThreadContextClassLoaderUpdate" with "invoke"

[14:15:01 CDT(-0500)] <athena1> ok

[14:15:51 CDT(-0500)] <athena1> running build, we'll see how it does

[14:25:12 CDT(-0500)] <athena1> http://pastebin.com/WhX2N1Et

[14:25:32 CDT(-0500)] <EricDalquist> hrm

[14:25:40 CDT(-0500)] <EricDalquist> ok I'm going to have to look into this more

[14:25:48 CDT(-0500)] <EricDalquist> but I'm not going to have a chance until this evening

[14:26:07 CDT(-0500)] <EricDalquist> its just futzing with the AOP interceptor to get it to work both programmatically and via the spring aop support

[14:29:40 CDT(-0500)] <athena1> ok

[14:29:42 CDT(-0500)] <athena1> hmm.

[14:29:51 CDT(-0500)] <athena1> in that case i'm wondering if we should back out the recent changes

[14:30:19 CDT(-0500)] <athena1> is there a reasonably easy way to do that with git?

[14:31:19 CDT(-0500)] <EricDalquist> I think "git revert commitid, commitid, ...." will do it

[14:31:29 CDT(-0500)] <EricDalquist> essentially reverse-patch those commits

[14:32:45 CDT(-0500)] <athena1> ok

[14:32:48 CDT(-0500)] <athena1> will try (smile)

[14:33:45 CDT(-0500)] <athena1> you have a good sense of which commits i should revert? all the ones from 4 days ago?

[14:34:57 CDT(-0500)] <EricDalquist> a bunch

[14:35:12 CDT(-0500)] <EricDalquist> looking at gitk anything that has UP-3466 in the commit message

[14:35:31 CDT(-0500)] <EricDalquist> looks like 4 + a merge commit

[14:35:38 CDT(-0500)] <athena1> ok

[14:47:27 CDT(-0500)] <athena1> ugh, i think i'm just making a mess

[14:48:03 CDT(-0500)] <EricDalquist> yeah the danger with the revert is if any commit since the one you're trying to revert touches a related file

[14:48:39 CDT(-0500)] <athena1> yeah.

[14:49:10 CDT(-0500)] <athena1> what a headline: "No new reports of tiger loose near Puyallup, Wash."

[14:49:46 CDT(-0500)] <EricDalquist> lol

[14:50:01 CDT(-0500)] <athena1> i'm like umm. . . what??