In this post I'm going to share what we did to diagnose the problem and what other hurdles we encountered on the way.
Up until this incident, I had practically zero experience troubleshooting Oracle middleware/weblogic/OMS problems, so I knew it was going to be frustrating, even with Oracle Support's assistance. The key was knowing where to look.
ldap_trace.logATN
The first log file that helped was $MIDDLEWARE_HOME/gc_inst/user_projects/domains/GCDomain/ldap_trace.logATN. From there I could see that my user was actually authenticating to the AD/LDAP successfully!12:13:20.490 ldc=999 op=997 SearchRequest {baseObject=OU=bar,DC=foo,DC=com, scope=2, derefAliases=0,sizeLimit=1000, timeLimit=120000, attrsOnly=false, filter=(&(&(sAMAccountName=dseiler)(objectclass=user)(!(objectclass=computer)))(!(userAccountControl:9.9.9.999999.9.9.999:=9))), attributes=1.1}
12:13:20.491 ldc=999 op=997 SearchResponse {entry='CN=Don Seiler,OU=bar,DC=foo,DC=com', attributes=''}
12:13:20.491 ldc=999 op=997 SearchResult {resultCode=0}
12:13:20.492 ldc=997 op=998 BindRequest {version=3, name=CN=Don Seiler,OU=bar,DC=foo,DC=com, authentication=********}
12:13:20.503 ldc=997 op=998 BindResponse {resultCode=0}
You can see that it first looks for my user, and once it finds a match it tries to bind as that user. The result code of 0 in the BindResponse indicates success.
So then it was clear that the problem was in the Oracle middleware forest somewhere.
Note: I changed some numeric values in the LDAP trace to provide a measure of security for my organization.
emoms.trc
The next place to look for problems was $MIDDLEWARE_HOME/gc_inst/em/EMGC_OMS1/sysman/log/emoms.trc. This gave me a detailed trace of everything that was being done when I attempted to authenticate. From there I could see that my user was authenticating and information being retrieved, but it was always failing here:2014-01-08 12:37:50,032 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG auth.EMLoginService parseLDAPAttributeMapping.356 - Fetched value null for attribute oracle.sysman.core.security.auth.ldapuserattributes_emuserattributes_mappings
2014-01-08 12:37:50,033 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG auth.EMLoginService parseLDAPAttributeMapping.290 - Parsing ldapattr, strings are: [null]
2014-01-08 12:37:50,034 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG auth.EMLoginService parseLDAPAttributeMapping.294 - After removing escape seq, strings are: [null]
2014-01-08 12:37:50,035 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG auth.EMLoginService _performLogin.1250 - Error
java.lang.ArrayIndexOutOfBoundsException: 1
at oracle.sysman.emSDK.sec.auth.EMLoginService.parseLDAPAttributeMapping(EMLoginService.java:308)
at oracle.sysman.emSDK.sec.auth.EMLoginService.parseLDAPAttributeMapping(EMLoginService.java:360)
... Rest of stack trace omitted ...
Looks like it was trying to parse the LDAP user attributes mappings value, which we had set to null since it wasn't in use prior to upgrade. This exception was propagated up until the entire login process was deemed to have failed:
2014-01-08 12:37:50,037 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG conn.FGAConnection fgaClose.320 - Connection object closed: 1892249056
2014-01-08 12:37:50,038 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] DEBUG auth.EMLoginService _performLogin.1260 - Exit: Fail
2014-01-08 12:37:50,039 [[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'] WARN auth.EMRepLoginFilter doFilter.457 - InvalidEMUserException caught in EMRepLoginFilter: Failed to login using external authentication for user: dseiler
oracle.sysman.emSDK.sec.auth.InvalidEMUserException: Failed to login using external authentication for user: dseiler
at oracle.sysman.emSDK.sec.auth.EMLoginService._performLogin(EMLoginService.java:1269)
at oracle.sysman.emSDK.sec.auth.EMLoginService._doSSOLogin(EMLoginService.java:754)
at oracle.sysman.emSDK.sec.auth.EMLoginService.doSSOLogin(EMLoginService.java:727)
... Rest of stack trace omitted ...
I asked Oracle Support a few times if they thought I should set the attribute mapping value just as a test, a question which went unanswered. After a day we decided to set it to just map the loginid to the username:
$ emctl set property -name oracle.sysman.core.security.auth.ldapuserattributes_emuserattributes_mappings -value "USERNAME={%loginid%}"
... and VOILA. Authentication worked! We could create new users manually or let users be auto-provisioned. But this was just the beginning ...
Auto-Provisioning Problems
Having authentication working and having been exposed to attribute mapping, we decided to give it a try and have the email and telephone fields be populated from the LDAP information.No Nulls Allowed
The first problem we noticed was users could not be provisioned if one of the mapped values was null, throwing a NullPointerException in the emoms.trc file. So if Tom Smith didn't have his phone number set, we couldn't provision a user for him. Nor could he auto-provision himself, both methods failed. Oracle Support told me this was a known bug, although I do not yet have a bug number to refer to.Last User Wins
The second problem with attribute mapping was that rather than fetching the information for just the user being provisioned, EM was getting a list of all the users (apparent in the emoms.trc file) and then choosing the values for the last user in the list. In our case it was always the most recent hire, so everyone that was auto-provisioned had their phone and email fields populated as if they were this person, with the exception of the loginid field. This problem only occurred during auto-provisioning though. If we manually provisioned the user, the LDAP attribute mapping worked as expected. I demonstrated this to Oracle Support via a shared screen, and they have just confirmed it in their lab and created Bug 18109783 - 12CR3: AUTOPROVISION FOR USER POPULATES INCORRECT USER ATTRIBUTE AFTER LOGIN.So in light of these two problems, we're only mapping the loginid field again. We don't rely on EM12c as an addressbook so it isn't a concern as yet, and users can easily update their email address manually for now if they need notifications. Eventually though it would be nice to see these fields mapped correctly.
UPDATE: 12 March 2014
Oracle Support have given me this OMS patch for my bug:
Patch 18109783 : 12CR3: AUTOPROVISION FOR USER POPULATES INCORRECT USER ATTRIBUTE AFTER LOGIN
I've just gotten the news, haven't had a chance to test it yet.
UPDATE: 14 March 2014
We applied the patch and confirm that it fixes the "Last User Wins" bug. We also found that the bug affected logins of existing users. EM was grabbing data from Active Directory for existing users even if they were already provisioned in EM. That hit us today with a new entry was made in our Active Directory that ended up breaking LDAP authentication for everyone in EM12c. Applying the patch avoided this, and we were quickly back up and running.
UPDATE: 18 March 2014
The NullPointerException auto-provisioning bug is still being worked on:Bug 18048421 : AUTO-PROVISIONING FAILS IF CONTACT DETAILS ARE NOT AVAILABLE FOR A USER
That leads to DocID 1635786.1, which says that this bug is patched for the 12.1.0.3 OMS in patch 18109783. This confuses me since I just patched for this but doesn't seem to be working.