jasig-cas IRC Logs-2011-09-19

Owned by Apereo Infrastructure
Last updated: Sept 19, 2011Version comment
6 min read

[14:11:05 CDT(-0500)] <brandon__> hello, i'm having a problem with setting up ldap with the bundled cas in uportal
[14:11:18 CDT(-0500)] <brandon__> i followed this guide: https://wiki.jasig.org/display/UPM32/Configuring+the+Bundled+CAS+Server+to+Authenticate+Against+LDAP
[14:11:25 CDT(-0500)] <brandon__> if there is a problem with any of the setup i did (dependencies, etc...) shouldn't i see an error?
[14:11:31 CDT(-0500)] <brandon__> all i see in the logs is that it "failed to authenticate"
[14:12:21 CDT(-0500)] <serac> Should be detailed logs in the application log file.
[14:12:40 CDT(-0500)] <serac> I have no idea where UP logging configuration lives, but likely in a log4j.properties or .xml file on the classpath.
[14:12:53 CDT(-0500)] <serac> Do you have a file like that?
[14:13:29 CDT(-0500)] <brandon__> hmm
[14:13:32 CDT(-0500)] <brandon__> i'll have to look
[14:13:46 CDT(-0500)] <brandon__> what would the log file be called?
[14:14:04 CDT(-0500)] <EricDalquist> here is the default cas log file for uPortal 3.2: https://source.jasig.org/uPortal/branches/rel-3-2-patches/uportal-portlets-overlay/cas/src/main/resources/log4j.properties
[14:14:17 CDT(-0500)] <EricDalquist> that should end up in webapps/cas/WEB-INF/classes
[14:17:11 CDT(-0500)] <brandon__> ok, it's cas.log in my tomcat logs folder
[14:17:26 CDT(-0500)] <brandon__> ?
[14:21:14 CDT(-0500)] <serac> You have such a file?
[14:21:49 CDT(-0500)] <brandon__> yeah
[14:21:59 CDT(-0500)] <brandon__> a bunch of INFO lines
[14:22:09 CDT(-0500)] <brandon__> the DEBUG line is telling me that authentication failed
[14:22:30 CDT(-0500)] <brandon__> there's a WARN line that says: 807 support.ResourceBundleMessageSource.[] - ResourceBundle [default] not found for MessageSource: Can't find bundle for base name default, locale en_US
[14:23:42 CDT(-0500)] <brandon__> a debug line tells me that it is performing LDAP bind with credential: my ldap string
[14:23:51 CDT(-0500)] <serac> ok
[14:26:04 CDT(-0500)] <brandon__> so it seems that ldap is setup correctly as far as cas is concerned, right?
[14:26:28 CDT(-0500)] <serac> Dunno.
[14:26:31 CDT(-0500)] <serac> Echo that debug line.
[14:27:45 CDT(-0500)] <brandon__> Sep/19 14:37:29,883 ldap.FastBindLdapAuthenticationHandler.[] - Performing LDAP bind with credential: uid=student,ou=Campus Users,dc=hccc,dc=campus
[14:28:15 CDT(-0500)] <serac> Yeah, looks like CAS is configured correctly in a broad sense.
[14:28:29 CDT(-0500)] <serac> Echo your (redacted) fast bind handler bean definition.
[14:31:19 CDT(-0500)] <brandon__> http://pastebin.com/FaGC6fP8
[14:31:49 CDT(-0500)] <serac> There's no uid attribute afaik in Active Directory.
[14:32:10 CDT(-0500)] <serac> I believe you mean sAMAccountname=%u,ou=...
[14:33:33 CDT(-0500)] <brandon__> ok, i can try that
[14:40:18 CDT(-0500)] <brandon__> didn't work, nothing new in the log either
[14:41:20 CDT(-0500)] <serac> Add the following line to your cas log config:
[14:41:46 CDT(-0500)] <serac> Wait...
[14:41:55 CDT(-0500)] <serac> Did you uncomment the following line Eric quoted:
[14:42:00 CDT(-0500)] <serac> #log4j.logger.org.jasig.cas.authentication=DEBUG
[14:42:19 CDT(-0500)] <serac> line from the file Eric quoted
[14:42:57 CDT(-0500)] <brandon__> ok, uncommented in the config file in webapps/cas/WEB-INF/classes
[14:43:02 CDT(-0500)] <brandon__> do i need to restart anything?
[14:43:18 CDT(-0500)] <serac> I would restart to ensure change takes effect.
[14:43:52 CDT(-0500)] <serac> I believe we use a component that monitors log4j config file for changes, but we want to avoid uncertainty in this case.
[14:46:10 CDT(-0500)] <brandon__> what i am looking for with that log config change
[14:46:15 CDT(-0500)] <brandon__> am i
[14:47:14 CDT(-0500)] <serac> More information following the bind attempt.
[14:47:27 CDT(-0500)] <serac> We may need to turn up org.springframework categories as well.
[14:48:18 CDT(-0500)] <brandon__> http://pastebin.com/7j1eA80X
[14:48:59 CDT(-0500)] <serac> Time to turn up Spring logging:
[14:48:59 CDT(-0500)] <serac> log4j.logger.org.springframework.ldap=DEBUG
[14:49:10 CDT(-0500)] <serac> Put that in your log config and restart+retry.
[14:50:22 CDT(-0500)] <brandon__> ok, i'm doing it in the right config file, right? /usr/local/tomcat/webapps/cas/WEB-INF/classes/log4j.properties
[14:51:26 CDT(-0500)] <serac> If that's where your deployed servlet apps live, yes.
[14:55:11 CDT(-0500)] <brandon__> http://pastebin.com/1BMZJzAr
[14:56:26 CDT(-0500)] <serac> Post your log4j.properties file.
[15:00:34 CDT(-0500)] <brandon__> http://pastebin.com/qiYadUhM
[15:05:32 CDT(-0500)] <serac> Good God.
[15:05:56 CDT(-0500)] <serac> Code review shows we provide no way to log the underlying NamingException that would provide helpful diagnostics in this case.
[15:06:01 CDT(-0500)] <serac> Boo.
[15:07:14 CDT(-0500)] <serac> Filing improvement Jira issue.
[15:07:44 CDT(-0500)] <EricDalquist> isn't it fun finding swallowed exceptions serac?
[15:08:07 CDT(-0500)] <serac> About as fun as stubbing your tow in the dark (wink)
[15:08:13 CDT(-0500)] <EricDalquist> yup
[15:08:18 CDT(-0500)] <serac> s/tow/toe/
[15:08:36 CDT(-0500)] <EricDalquist> I got so fed up at one point a few years ago in uPortal I actually did a search for every catch and every new *Exception
[15:08:49 CDT(-0500)] <EricDalquist> and spent 2 days going through and making sure all exceptions were either chained or logged
[15:08:53 CDT(-0500)] <serac> Wow, that's impressive.
[15:09:14 CDT(-0500)] <serac> There's a reason there's a checkstyle rule for an empty catch block (wink)
[15:09:15 CDT(-0500)] <EricDalquist> it was getting to the point where every other day I was running into a missing stack trace
[15:09:33 CDT(-0500)] <EricDalquist> we had a log of: log.error("something bad happened: " + e);
[15:09:37 CDT(-0500)] <EricDalquist> which is less than useful
[15:09:53 CDT(-0500)] <serac> There are limited cases for those, but yeah, generally, provide the cause.
[15:10:50 CDT(-0500)] <EricDalquist> yeah, the few places we need those we do:
[15:10:50 CDT(-0500)] <EricDalquist> if (logger.isDebugEnabled()) {
[15:10:56 CDT(-0500)] <EricDalquist> log.error("something bad happened", e);
[15:10:56 CDT(-0500)] <EricDalquist> }
[15:10:57 CDT(-0500)] <EricDalquist> else {
[15:10:57 CDT(-0500)] <EricDalquist> log.error("something bad happened: " + e);
[15:10:57 CDT(-0500)] <EricDalquist> }
[15:11:06 CDT(-0500)] <serac> Ah, that's a nice idiom.
[15:11:06 CDT(-0500)] <EricDalquist> so you can at least tweak logging to see the stack
[15:11:20 CDT(-0500)] <EricDalquist> yeah
[15:11:37 CDT(-0500)] <EricDalquist> I've been tempted to write a Logger wrapper to provide that as a single method
[15:12:13 CDT(-0500)] <brandon__> (sad)
[15:12:15 CDT(-0500)] <serac> Lots of big projects provide logging wrappers that do that kind of thing.
[15:12:24 CDT(-0500)] <brandon__> so there's no way of telling what is causing the problem?
[15:12:26 CDT(-0500)] <serac> Brandon: https://issues.jasig.org/browse/CAS-1047.
[15:12:41 CDT(-0500)] <serac> I can ship out a patch toute de suite if you want to build from source.
[15:13:42 CDT(-0500)] <brandon__> i'd have to rebuild uportal again?
[15:13:48 CDT(-0500)] <serac> Uh, that's right.
[15:14:00 CDT(-0500)] <serac> You're using the bundled CAS stuff, right?
[15:14:03 CDT(-0500)] <brandon__> yeah
[15:14:28 CDT(-0500)] <serac> Do you happen to know the underlying CAS version?
[15:14:45 CDT(-0500)] <EricDalquist> brandon__: that is listed in the root uPortal pom.xml
[15:14:51 CDT(-0500)] <EricDalquist> in the <properties> block
[15:15:29 CDT(-0500)] <brandon__> 3.3.5
[15:15:53 CDT(-0500)] <serac> Hmmm.
[15:17:13 CDT(-0500)] <serac> I can send you a patched jar for that version.
[15:17:24 CDT(-0500)] <brandon__> that'd be great
[15:17:25 CDT(-0500)] <serac> You'd just drop it in WEB-INF/lib.
[15:17:50 CDT(-0500)] <brandon__> then i should watch the logs again?
[15:17:52 CDT(-0500)] <EricDalquist> note that the patches jar from serac will not support local auth with uportal brandon__
[15:17:59 CDT(-0500)] <EricDalquist> er
[15:18:00 CDT(-0500)] <EricDalquist> may not
[15:18:02 CDT(-0500)] <brandon__> my current config is all right
[15:18:05 CDT(-0500)] <brandon__> ?
[15:18:08 CDT(-0500)] <EricDalquist> but that shouldn't matter for your testing
[15:18:11 CDT(-0500)] <EricDalquist> actually wait
[15:18:13 CDT(-0500)] <EricDalquist> never mind
[15:18:16 CDT(-0500)] <EricDalquist> ignore all of that
[15:18:19 CDT(-0500)] <brandon__> yeah, i can just replace it right?
[15:18:20 CDT(-0500)] <brandon__> ok
[15:18:24 CDT(-0500)] <serac> I think this will be ok. I'm just sending the LDAP integration jar.
[15:18:33 CDT(-0500)] <serac> Should be drop-in compatible, np.
[15:20:51 CDT(-0500)] <serac> Email?
[15:20:57 CDT(-0500)] <serac> Or you can ping me privately.
[15:26:19 CDT(-0500)] <serac> With org.jasig.cas.authentication at DEBUG you should see the stack trace. Post that when you get it.
[15:29:12 CDT(-0500)] <brandon__> there we go
[15:29:13 CDT(-0500)] <brandon__> http://pastebin.com/a2zyV7aK
[15:31:32 CDT(-0500)] <serac> Aha.
[15:31:41 CDT(-0500)] <serac> You don't trust yourself.
[15:32:12 CDT(-0500)] <serac> (I've assumed this is all running on one box.)
[15:32:31 CDT(-0500)] <brandon__> yeah
[15:32:33 CDT(-0500)] <serac> Actually it's not a case of self-trust.
[15:32:45 CDT(-0500)] <serac> It's that you don't trust the cert on your AD domain controller.
[15:33:02 CDT(-0500)] <brandon__> ldap?
[15:33:11 CDT(-0500)] <brandon__> uportal and cas are all on one box
[15:33:22 CDT(-0500)] <serac> Grab the cert on 172.16.6.115 and install it into your machine's system truststore, $JRE_HOME/lib/security/cacerts.
[15:33:45 CDT(-0500)] <brandon__> ok, that's because i'm using ldaps?
[15:33:50 CDT(-0500)] <serac> Correct.
[15:34:42 CDT(-0500)] <brandon__> so would it be similar to what i did to setup ssl on cas? https://wiki.jasig.org/display/UPM32/SSL+Configuration
[15:35:07 CDT(-0500)] <brandon__> i know how to get the cert with openssl, just not how to install it into my store
[15:35:38 CDT(-0500)] <serac> It's a different command.
[15:35:45 CDT(-0500)] <serac> Slightly.
[15:36:50 CDT(-0500)] <serac> I would recommend installing the issuer cert of the AD cert into your truststore.
[15:36:58 CDT(-0500)] <serac> Makes for easier management.
[15:37:32 CDT(-0500)] <serac> In any case it's still a keytool -import command.
[15:38:02 CDT(-0500)] <brandon__> so how would i get the issuer cert of the AD cert?
[15:39:02 CDT(-0500)] <serac> Depends on the issuer. If it's self-signed, the subject and issuer are same. Use a browser or openssl s_client or similar to determine issuer, which will determine next step.
[15:39:14 CDT(-0500)] <brandon__> ok
[15:39:26 CDT(-0500)] <brandon__> thank you both for your help