API KEY Based access slow down the SCM-Manager

I have observed that the SCM-Manager would slowdown while managing the API-KEY based requests with the SVN clients.

  1. SCM-Manager: v2.3.40
  2. SVN-KIT: Default
  3. LDAP Integrated: YES
  4. LDAP CLient version: v2.4.0
  5. API-KEY Created: YES

It would try to check the LDAP authentication eventhough API-KEY is supplied.

How to reproduce:

  1. Integrate the SCM-Manager with the Active directory server of ANY
  2. Enable LDAP Log in
  3. Create READ-WRITE API KEY
  4. Try checkout/checkin authenticating with API-KEY: MUCH Slower
  5. Try checkout/checkin authenticating with LDAP credentials: MUCH Faster

LOGS:

2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.authc.pam.ModularRealmAuthenticator - Realm [com.cloudogu.scm.ces.serviceaccount.CesTokenRealm@4813d0] does not support token org.apache.shiro.authc.UsernamePasswordToken - girish.kg@mydomain.com, rememberMe=false.  Skipping realm.
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG sonia.scm.security.DAORealmHelper - try to authenticate girish.kg@mydomain.com
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - Looked up AuthenticationInfo [girish.kg@mydomain.com,User{name=girish.kg@mydomain.com, displayName=Girish KG, mail=girish.kg@mydomain.com, password=(not set), type=null, active=true, external=true, creationDate=1637610527758, lastModified=1652758196858, properties=null},[]] from doGetAuthenticationInfo
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - AuthenticationInfo caching is disabled for info [girish.kg@mydomain.com,User{name=girish.kg@mydomain.com, displayName=Girish KG, mail=girish.kg@mydomain.com, password=(not set), type=null, active=true, external=true, creationDate=1637610527758, lastModified=1652758196858, properties=null},[]].  Submitted token: [org.apache.shiro.authc.UsernamePasswordToken - girish.kg@mydomain.com, rememberMe=false].
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG sonia.scm.security.ConfigurableLoginAttemptHandler - login attempts LoginAttempt{counter=0, lastAttempt=-1} of girish.kg@mydomain.com are timetout
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.authc.pam.ModularRealmAuthenticator - Realm [sonia.scm.security.DefaultRealm@2d4f67e] threw an exception during a multi-realm authentication attempt:
java.lang.IllegalArgumentException: Stored account credentials are expected to be either a org.apache.shiro.crypto.hash.Hash instance or a formatted hash String.
        at org.apache.shiro.authc.credential.PasswordMatcher.assertStoredCredentialsType(PasswordMatcher.java:91)
        at org.apache.shiro.authc.credential.PasswordMatcher.doCredentialsMatch(PasswordMatcher.java:48)
        at sonia.scm.security.DAORealmHelper$RetryLimitPasswordMatcher.doCredentialsMatch(DAORealmHelper.java:238)
        at org.apache.shiro.realm.AuthenticatingRealm.assertCredentialsMatch(AuthenticatingRealm.java:600)
        at org.apache.shiro.realm.AuthenticatingRealm.getAuthenticationInfo(AuthenticatingRealm.java:581)
        at org.apache.shiro.authc.pam.ModularRealmAuthenticator.doMultiRealmAuthentication(ModularRealmAuthenticator.java:225)
        at org.apache.shiro.authc.pam.ModularRealmAuthenticator.doAuthenticate(ModularRealmAuthenticator.java:275)
        at org.apache.shiro.authc.AbstractAuthenticator.authenticate(AbstractAuthenticator.java:198)
        at org.apache.shiro.mgt.AuthenticatingSecurityManager.authenticate(AuthenticatingSecurityManager.java:106)
        at org.apache.shiro.mgt.DefaultSecurityManager.login(DefaultSecurityManager.java:275)
        at org.apache.shiro.subject.support.DelegatingSubject.login(DelegatingSubject.java:260)
        at sonia.scm.web.filter.AuthenticationFilter.handleAuthentication(AuthenticationFilter.java:224)
        at sonia.scm.web.filter.AuthenticationFilter.doFilter(AuthenticationFilter.java:109)
        at sonia.scm.web.filter.HttpFilter.doFilter(HttpFilter.java:93)
        at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
        at sonia.scm.security.TokenExpiredFilter.doFilter(TokenExpiredFilter.java:66)
        at sonia.scm.web.filter.HttpFilter.doFilter(HttpFilter.java:93)
        at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
        at sonia.scm.filter.BaseUrlFilter.doFilter(BaseUrlFilter.java:73)
        at sonia.scm.web.filter.HttpFilter.doFilter(HttpFilter.java:93)
        at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
        at sonia.scm.metrics.HttpMetricsFilter.doFilter(HttpMetricsFilter.java:68)
        at sonia.scm.web.filter.HttpFilter.doFilter(HttpFilter.java:93)
        at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
        at org.apache.shiro.guice.web.SimpleFilterChain.doFilter(SimpleFilterChain.java:44)
        at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
        at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
        at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
        at org.apache.shiro.guice.web.SimpleFilterChain.doFilter(SimpleFilterChain.java:41)
        at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)
        at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)
        at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
        at org.apache.shiro.guice.web.SimpleFilterChain.doFilter(SimpleFilterChain.java:41)
        at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:450)
        at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
        at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
        at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
        at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:387)
        at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
        at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
        at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:82)
        at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:121)
        at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:133)
        at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201)
        at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
        at org.eclipse.jetty.server.Server.handle(Server.java:516)
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:400)
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:392)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG sonia.scm.store.JAXBConfigurationStore - load class com.cloudogu.scm.cas.Configuration from store /svndata/config/cas.xml
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG com.cloudogu.scm.cas.rest.CasRestRealm - cas authentication is disabled, skipping cas rest realm
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - Looked up AuthenticationInfo [null] from doGetAuthenticationInfo
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - No AuthenticationInfo found for submitted AuthenticationToken [org.apache.shiro.authc.UsernamePasswordToken - girish.kg@mydomain.com, rememberMe=false].  Returning null.
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.authc.pam.ModularRealmAuthenticator - Realm [com.cloudogu.scm.cas.browser.CasTokenRealm@41167ded] does not support token org.apache.shiro.authc.UsernamePasswordToken - girish.kg@mydomain.com, rememberMe=false.  Skipping realm.
2022-05-16 20:30:23.504 [qtp204349222-1175] [          ] DEBUG org.apache.shiro.authc.AbstractAuthenticator - Authentication successful for token [org.apache.shiro.authc.UsernamePasswordToken - girish.kg@mydomain.com, rememberMe=false].  Returned account [girish.kg@mydomain.com,User{name=girish.kg@mydomain.com, displayName=Girish, mail=girish.kg@mydomain.com, password=(not set), type=null, active=true, external=true, creationDate=null, lastModified=null, properties=null}]

Thank you @girishkg for your report.
We will have a look at it and will come back to you soon

1 Like

Hey @girishkg , we just released version 2.5.0 of the LDAP plugin for SCM-Manager. We implemented a small cache, where credentials rejected by the LDAP server are held for 5 seconds, so that further requests to the LDAP server in this time will be prevented. Succesful authentications have been cached for a long time, already.

Can you check if this works for you? We did not change the inherent workflow in SCM-Manager, that each authentication is sent to all authentication providers.

1 Like

is this new version of the plugin compatible with SCM-Manager 2.29.1?

Hey @mcote,

yes it is. https://scm-manager.org/plugins/scm-ldap-plugin/releases/

BR, Eduard

Hi @pfeuffer
Yes, this has fixed the flooding LDAP AUTH attempts. The logs doesn’t show those failures now.
Thanks for bringing in the required changes within in a short period.

The latest LDAP plugin 2.5.0 has slowed it down.
I see the logs are coming back after a while.

2022-06-13 22:29:33.159 [qtp1642534850-93] [          ] DEBUG sonia.scm.security.DAORealmHelper - try to authenticate svcbuildm
2022-06-13 22:29:33.159 [qtp1642534850-93] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - Looked up AuthenticationInfo [svcbuildm,User{name=svcbuildm, displayName=SVC Build Manager, mail=svcbuildm@swinfra.net, password=(is set), type=xml, active=true, external=false, creationDate=1637610741705, lastModified=null, properties={}},["repository:read,pull,push,readStatistics,createPullRequest,readPullRequest,commentPullRequest,mergePullRequest,readCIStatus:*"],svcbuildm] from doGetAuthenticationInfo
2022-06-13 22:29:33.159 [qtp1642534850-93] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - AuthenticationInfo caching is disabled for info [svcbuildm,User{name=svcbuildm, displayName=SVC Build Manager, mail=svcbuildm@swinfra.net, password=(is set), type=xml, active=true, external=false, creationDate=1637610741705, lastModified=null, properties={}},["repository:read,pull,push,readStatistics,createPullRequest,readPullRequest,commentPullRequest,mergePullRequest,readCIStatus:*"],svcbuildm].  Submitted token: [org.apache.shiro.authc.UsernamePasswordToken - svcbuildm, rememberMe=false].
2022-06-13 22:29:33.159 [qtp1642534850-93] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - Looked up AuthenticationInfo [null] from doGetAuthenticationInfo
2022-06-13 22:29:33.159 [qtp1642534850-93] [          ] DEBUG org.apache.shiro.realm.AuthenticatingRealm - No AuthenticationInfo found for submitted AuthenticationToken [org.apache.shiro.authc.UsernamePasswordToken - svcbuildm, rememberMe=false].  Returning null.

Hey @girishkg
Thanks for the feedback! Just let me get it straight: Are you flooded by logs again after some time or do you get them just every few seconds? The cache for the ldap realm is configured to reject credentials that have failed once for five seconds, so I would expect ldap requests for a single user with an api key every five seconds or so with continuous access.

Hi @pfeuffer ,
Logs are less frequent and I see the improvement in the performance.

Hi @girishkg and @mcote we haven’t heard from you.

We hope that your issues are solved and that everything is fine.
If not please do not hestitate to post your findings :slight_smile: