A question about load balancers and Terracotta clustering

[Wessel, Keith William]

All,

Matched my versions of things with the versions Chris is using (thanks, Chris), but with the problem continuing.

However, today I found a smoking gun in the Tomcat localhost log. A nullpointer exception which seems to correspond with the function the IDP's performing. I got this same error in the logs on my older version 6.0.20 as well as my upgrade today to Tomcat 6.0.35. Looking back, this error has been popping up in the localhost log for Tomcat ever since the problem started, in fact. Error is below, please forgive the Java stack trace.

I searched the archives for similar errors and, other than Russ's problems with multitab issues when he moved to 2.3.3 last August, I saw nothing relevant here. Makes me wonder what strange and painful thing I may have accidentally done here.

Can anyone who knows the internals tell me what might be causing this? Again, any help would be appreciated.

Keith

Jul 17, 2012 4:07:34 PM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet AuthenticationEngine threw exception java.lang.NullPointerException
	at javax.security.auth.Subject$ClassSet.<init>(Subject.java:1311)
	at javax.security.auth.Subject.getPrincipals(Subject.java:592)
	at edu.internet2.middleware.shibboleth.idp.session.impl.SessionImpl.__tc_wrapped_getPrincipalName(SessionImpl.java:99)
	at edu.internet2.middleware.shibboleth.idp.session.impl.SessionImpl.getPrincipalName(SessionImpl.java)
	at edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.startUserAuthentication(AuthenticationEngine.java:244)
	at edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine.service(AuthenticationEngine.java:223)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:81)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.terracotta.modules.tomcat.tomcat_5_5.SessionValve55.invoke(SessionValve55.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
	at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
	at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
	at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776)
	at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705)
	at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
	at java.lang.Thread.run(Thread.java:662)

-----Original Message-----
From: Wessel, Keith William 
Sent: Monday, July 16, 2012 4:16 PM
To: 'Shib Users'
Subject: RE: A question about load balancers and Terracotta clustering

Just confirming that this isn't an issue...

When running the tim-get.sh commands to install tim-vector and tim-tomcat-6.0, I've fallen into the practice in the past of just leaving off the version number and getting the latest version. The versions referenced in the Wiki documentation on setting up a Shibboleth IDP cluster with Terracotta refer to tim-tomcat-6.0 2.1.3 which isn't available any more. So, recently, I've been using tim-vector 2.7.1 and tim-tomcat-6.0 2.3.2. Is this what others are doing, as well? Just making sure this isn't the source of my problems.

My last attempt is a Tomcat upgrade. I doubt this will help, but I'm going to give it a shot. We're still on 6.0.20.

Keith


-----Original Message-----
From: Wessel, Keith William 
Sent: Monday, July 16, 2012 11:51 AM
To: 'Shib Users'
Subject: RE: A question about load balancers and Terracotta clustering

Hi, all,

Not making much progress on this, even with the dev console. I'm hoping there's something else I should be looking for in the dev console.

I only have my active server node running, no passive node in stand-by... just to avoid confusion.

I log into IDP node 1 successfully, and I see the session created in Terracotta in the dev console.

I then shut down IDP node 1 and restart shibd and apache on the SP. I log into IDP node 2, or try to... but I get the error screen (with no specific error) from the IDP. Same trace-level log messages as I reported in my previous message below. Nothing noticeable is updated in the session in Terracotta. The last activity time corresponds to when I logged into node 1 and created the session, not when I hit node 2.

Same exact thing happens when I start with node 2 then try to hit node 1. So, it's not an issue with node 2 communicating with the server. Rather, it seems to be an issue with updating existing sessions.

Anyone have any thoughts on what might be causing this and where else I might look?

Thanks,
Keith




-----Original Message-----
From: Wessel, Keith William 
Sent: Wednesday, July 11, 2012 1:31 PM
To: 'Shib Users'
Subject: RE: A question about load balancers and Terracotta clustering

All,

Still on the trail over here, and decided to turn some logging up to "ALL" to see what the TRACE and other items told me. An interesting tidbit. Here's where the logging seems to end:

11:31:30.240 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] [session=] - Attempting to retrieve IdP session cookie.
11:31:30.241 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:115] [session=] - Found IdP session cookie.
11:31:30.244 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:75] [session=] - Updating IdP session activity time and adding session object to the request

Seems like something's happening when the IDP tries to write back to the Terracotta store at this point. I see no logs, client or server, on the Terracotta side corresponding with this timestamp, and I'm unclear how to turn up logging for Terracotta. Any suggestions on either getting more in the idp-process.log or the terracotta logs at this point from anyone would be very much appreciated.

Also, can I assume that this means the session was successfully RETRIEVED from the Terracotta store at this point based on what the IDP found in the cookie? Just trying to figure out if I can even read into this that we're reading from the Terracotta store alright.

Thanks again, everyone, for all the help on this.

Keith


-----Original Message-----
From: Wessel, Keith William 
Sent: Monday, July 09, 2012 8:53 PM
To: Shib Users
Subject: RE: A question about load balancers and Terracotta clustering

Thank you, Gentlemen. Chris, I'll go for a newer Tomcat and Terracotta to see if that helps. Was hoping to avoid upgrading Tomcat, but it's probably just as well that I do.

Yep, the first thing I did today after upgrading Java and Terracotta (6.26 and 3.5.2 using files I'd downloaded several months ago when doing some other troubleshooting that's unrelated) was rebuilt the jar.

We've got our heap at a good size in production where the clustering appears to be working correctly on rhel4. But we need to get to rhel6 as soon as possible for production which means confirming that all's happy in our test cluster, of course.

I'm not optimistic that a Tomcat upgrade and Terracotta 3.5.3 rather than 3.5.2 is going to solve this. So, perhaps the next step is console.sh.

Keith


-----Original Message-----
From: users-bounces at shibboleth.net [mailto:users-bounces at shibboleth.net] On Behalf Of Russell Beall
Sent: Monday, July 09, 2012 5:03 PM
To: Shib Users
Subject: Re: A question about load balancers and Terracotta clustering

On RHEL 6 I had to install the Sun JDK and use that instead of the Open JDK installation.

There was also a difference or two in the options, but those were not for making the connections work.

Have you rerun the make-boot-jar.sh under your new environment?  (I think you may have already said you checked that...)

Regards,
Russ.

On Jul 9, 2012, at 2:08 PM, Wessel, Keith William wrote:

> One question as is seems our move to RHEL6 might have broken this. Can Russ or others tell me what Tomcat, Java and Terracotta version conbimations they've found to work? I'm wondering if it's time to update one or more of these.

--
To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net