Graylog2-server: Active Directory login test fails due to empty field validation

Created on 24 Aug 2016 · 8Comments · Source: Graylog2/graylog2-server

Expected Behavior

Assumptions:

Logged in to Graylog as administrator with local account.
Visiting graylogserver:9000/system/ldap to configure Active Directory.

Expected: if the connection test is successful using the bind account information (which is called "System Username" and "System Password" in the UI, and the other fields are filled out, validation that fields are nonempty should pass.

Current Behavior

All fields are filled out except the optional "Additional Default Roles" field. Thus, all required fields are nonblank. However, the error "Binding with empty principal is forbidden." appears when the Test Login button is clicked. (This error message was introduced in this commit: https://github.com/Graylog2/graylog2-server/commit/67b54471384e960e0517c865d6496cfc6376a930 )

Here is the relevant log portion from setting authentication logging to Trace. The only interesting thing seems to be the java.lang.NullPointerException:

2016-08-24T09:01:41.662-04:00 TRACE [ThreadContext] get() - in thread [rest-worker-4]
2016-08-24T09:01:41.662-04:00 TRACE [ThreadContext] Retrieved value of type [javax.ws.rs.core.MultivaluedHashMap] for key [REQUEST_HEADERS] bound to thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] Bound value of type [org.apache.shiro.subject.support.DelegatingSubject] for key [org.apache.shiro.util.ThreadContext_SUBJECT_KEY] to thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 DEBUG [AuthenticatingRealm] Looked up AuthenticationInfo [graylogroot] from doGetAuthenticationInfo
2016-08-24T09:01:41.670-04:00 DEBUG [AuthenticatingRealm] AuthenticationInfo caching is disabled for info [graylogroot].  Submitted token: [SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}].
2016-08-24T09:01:41.670-04:00 DEBUG [ModularRealmAuthenticator] Realm [org.graylog2.security.realm.AccessTokenAuthenticator@a308d6] does not support token SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}.  Skipping realm.
2016-08-24T09:01:41.670-04:00 DEBUG [ModularRealmAuthenticator] Realm [org.graylog2.security.realm.LdapUserAuthenticator@7a104fb9] does not support token SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}.  Skipping realm.
2016-08-24T09:01:41.670-04:00 DEBUG [ModularRealmAuthenticator] Realm [org.graylog2.security.realm.PasswordAuthenticator@67858a15] does not support token SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}.  Skipping realm.
2016-08-24T09:01:41.670-04:00 DEBUG [ModularRealmAuthenticator] Realm [org.graylog2.security.realm.GraylogSimpleAccountRealm@28170f26] does not support token SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}.  Skipping realm.
2016-08-24T09:01:41.670-04:00 DEBUG [AbstractAuthenticator] Authentication successful for token [SessionIdToken{sessionId=26c30d17-d176-4014-8a63-60d9fafa120f, host=10.25.111.237:12900}].  Returned account [graylogroot]
2016-08-24T09:01:41.670-04:00 DEBUG [DefaultSubjectContext] No SecurityManager available in subject context map.  Falling back to SecurityUtils.getSecurityManager() lookup.
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] get() - in thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [DefaultSecurityManager] Context already contains a SecurityManager instance.  Returning.
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = true; session has id = false
2016-08-24T09:01:41.670-04:00 DEBUG [DefaultSubjectContext] No SecurityManager available in subject context map.  Falling back to SecurityUtils.getSecurityManager() lookup.
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] get() - in thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = true; session has id = false
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = true; session has id = false
2016-08-24T09:01:41.670-04:00 TRACE [DefaultSubjectDAO] Session storage of subject state for Subject [org.apache.shiro.subject.support.DelegatingSubject@4633a06f] has been disabled: identity and authentication state are expected to be initialized on every request or invocation.
2016-08-24T09:01:41.670-04:00 TRACE [DefaultSecurityManager] This org.apache.shiro.mgt.DefaultSecurityManager instance does not have a [org.apache.shiro.mgt.RememberMeManager] instance configured.  RememberMe services will not be performed for account [graylogroot].
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = true; session has id = false
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] get() - in thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] Retrieved value of type [org.apache.shiro.subject.support.DelegatingSubject] for key [org.apache.shiro.util.ThreadContext_SUBJECT_KEY] bound to thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [ThreadContext] Removed value of type [javax.ws.rs.core.MultivaluedHashMap] for key [REQUEST_HEADERS]from thread [rest-worker-4]
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = false; session has id = true
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = false; session has id = true
2016-08-24T09:01:41.670-04:00 TRACE [DelegatingSubject] attempting to get session; create = false; session is null = false; session has id = true
2016-08-24T09:01:41.670-04:00 TRACE [AuthorizingRealm] Retrieving AuthorizationInfo for principals [graylogroot]
2016-08-24T09:01:41.670-04:00 TRACE [AuthorizingRealm] Attempting to retrieve the AuthorizationInfo from cache.
2016-08-24T09:01:41.670-04:00 TRACE [AuthorizingRealm] No AuthorizationInfo found in cache for principals [graylogroot]
2016-08-24T09:01:41.671-04:00 TRACE [AuthorizingRealm] Caching authorization info for principals: [graylogroot].
2016-08-24T09:01:41.806-04:00 WARN  [LdapNetworkConnection] java.lang.NullPointerException
org.apache.mina.filter.codec.ProtocolEncoderException: java.lang.NullPointerException
    at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:337) ~[graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:625) [graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1500(DefaultIoFilterChain.java:48) [graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.filterWrite(DefaultIoFilterChain.java:953) [graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.filterWrite(DefaultIoFilterChain.java:877) [graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callPreviousFilterWrite(DefaultIoFilterChain.java:625) [graylog.jar:?]
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireFilterWrite(DefaultIoFilterChain.java:618) [graylog.jar:?]
    at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:502) [graylog.jar:?]
    at org.apache.mina.core.session.AbstractIoSession.write(AbstractIoSession.java:447) [graylog.jar:?]
    at org.apache.directory.ldap.client.api.LdapNetworkConnection.writeRequest(LdapNetworkConnection.java:4073) [graylog.jar:?]
    at org.apache.directory.ldap.client.api.LdapNetworkConnection.searchAsync(LdapNetworkConnection.java:1752) [graylog.jar:?]
    at org.apache.directory.ldap.client.api.LdapNetworkConnection.search(LdapNetworkConnection.java:1778) [graylog.jar:?]
    at org.apache.directory.ldap.client.api.LdapNetworkConnection.search(LdapNetworkConnection.java:1671) [graylog.jar:?]
    at org.apache.directory.ldap.client.api.LdapNetworkConnection.search(LdapNetworkConnection.java:1681) [graylog.jar:?]
    at org.graylog2.security.ldap.LdapConnector.search(LdapConnector.java:133) [graylog.jar:?]
    at org.graylog2.rest.resources.system.ldap.LdapResource.testLdapConfiguration(LdapResource.java:168) [graylog.jar:?]
    at sun.reflect.GeneratedMethodAccessor193.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [graylog.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [graylog.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [graylog.jar:?]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:205) [graylog.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [graylog.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [graylog.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [graylog.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [graylog.jar:?]
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [graylog.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [graylog.jar:?]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [graylog.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [graylog.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [graylog.jar:?]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [graylog.jar:?]
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [graylog.jar:?]
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [graylog.jar:?]
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [graylog.jar:?]
    at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:384) [graylog.jar:?]
    at org.glassfish.grizzly.http.server.HttpHandler$1.run(HttpHandler.java:224) [graylog.jar:?]
    at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176) [graylog.jar:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_101]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_101]
    at java.lang.Thread.run(Thread.java:745) [?:1.8.0_101]
Caused by: java.lang.NullPointerException
    at org.apache.directory.api.ldap.codec.decorators.SearchRequestDecorator.computeLength(SearchRequestDecorator.java:927) ~[graylog.jar:?]
    at org.apache.directory.api.ldap.codec.api.LdapEncoder.computeMessageLength(LdapEncoder.java:248) ~[graylog.jar:?]
    at org.apache.directory.api.ldap.codec.api.LdapEncoder.encodeMessage(LdapEncoder.java:160) ~[graylog.jar:?]
    at org.apache.directory.api.ldap.codec.protocol.mina.LdapProtocolEncoder.encode(LdapProtocolEncoder.java:78) ~[graylog.jar:?]
    at org.apache.mina.filter.codec.ProtocolCodecFilter.filterWrite(ProtocolCodecFilter.java:306) ~[graylog.jar:?]
    ... 41 more

Possible Solution

If this is a configuration error instead of a bug, (for example, Graylog is expecting an OS system account with valid Kerberos tickets) then these prerequisites should be documented on http://docs.graylog.org/en/2.0/pages/users_and_roles/external_auth.html

Steps to Reproduce (for bugs)

Log in as admin and go to System / Users and LDAP Configuration.
Enter Server configuration, choosing Active Directory and SSL.
Do successful Connection Test.
Fill out User mapping info.
Fill out Group Mapping info.
Do Test login.

Context

Unable to authenticate against AD, which prevents us from implementing Graylog.

Your Environment

Graylog Version: 2.0.3
Elasticsearch Version: 2.3.5
MongoDB Version: 3.2.9
Operating System: RHEL 7.2
Browser version: Safari 9.1.2 (11601.7.7)

P3 S3 bug ldap triaged

Source

clouseau

👍2

All 8 comments

I just wanted to comment to say that I am seeing the same issue. I am currently using the latest 2.1.1 appliance.

It's not stopping us from using Graylog, but I would prefer to have LDAP authentication. I'm trying to authenticate against AD by the way.

rokett on 19 Sep 2016

👍1

Also in Graylog 2.1.1 we are experiencing the same issue when trying to connect to Microsoft Server 2012 R2. Getting the error message "Binding with empty principal is forbidden". Tried everything possible with the User mapping... Is there any bug fix available; that would be super awesome?

ps-gm on 20 Sep 2016

Any Updates on that one? Can we help in troubleshooting or fixing this?

ps-gm on 6 Oct 2016

Debugging LDAP/AD remotely is probably the worst exercise there is 😞

You can try setting the Graylog log level org.graylog2.security.ldap to TRACE (http://docs.graylog.org/en/2.1/pages/installation/manual_setup.html?highlight=log4j#supplying-external-logging-configuration)

Other than that, it looks to me like that the active directory server requires an immediate authentication, whereas other implementation allow an anonymous bind to test the connection and then rebind to establish the authentication.

I haven't seen this behavior before, but I'm also no overly familiar with Active Directory, to be honest.

kroepke on 6 Oct 2016

That's correct that AD doesn't allow anonymous binds by default; you have to supply credentials. Isn't that why you specify the system username and password in section 1?

Although it is possible to configure AD to allow anonymous binds, that's not a default behaviour and isn't generally a good idea. Is there anything that can be done in code to resolve this? I'm also happy to help where I can in testing changes as AD authentication is important to us.

rokett on 7 Oct 2016

I had the same issue, looks like your user search pattern is wrong.
I replaced it to:
(&(objectClass=user)(sAMAccountName={0}))
and it started to work for me.
BTW it also noted in the ldap config page to use this string.

yairmiz on 25 Oct 2016

I feel somewhat stupid now! :-)

My search pattern was correct but in looking over the settings again I realised that I'd messed up the search base DN. After correcting that, all is good!

Thanks Yairmiz for posting as it prompted me to look at the settings again.

rokett on 25 Oct 2016

👍1

For AD I'd recommend using user principal names instead of SAM account names. If correctly setup you should be able to use (&(objectClass=user)(userPrincipalName={0}))