API KEY Based access slow down the SCM-Manager

girishkg · May 27, 2022, 6:09pm

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

SCM-Manager: v2.3.40
SVN-KIT: Default
LDAP Integrated: YES
LDAP CLient version: v2.4.0
API-KEY Created: YES

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

How to reproduce:

Integrate the SCM-Manager with the Active directory server of ANY
Enable LDAP Log in
Create READ-WRITE API KEY
Try checkout/checkin authenticating with API-KEY: MUCH Slower
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}]

christoph.loose · May 30, 2022, 8:54am

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

pfeuffer · June 8, 2022, 8:26am

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.

mcote · June 8, 2022, 4:17pm

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

eheimbuch · June 9, 2022, 5:39am

Hey @mcote,

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

BR, Eduard

girishkg · June 14, 2022, 5:25am

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.

girishkg · June 14, 2022, 5:39am

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.

pfeuffer · June 14, 2022, 6:18am

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.

girishkg · June 14, 2022, 8:34am

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

christoph.loose · July 8, 2022, 11:00am

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

christoph.loose · December 27, 2022, 9:10am

I am closing this topic as there has been no activity for more than 30 days.

Topic		Replies	Views
SVN-KIT - svn: E140000: Can't read length line from file Bug Reports SCM-Manager	6	714	December 27, 2022
LDAP Configuration SCM-Manager	1	178	August 2, 2023
How to config LDAPs authentication in SCM-Manager SCM-Manager	1	227	March 1, 2023
Authenticating against multiple LDAP servers Plugins	3	129	February 9, 2024
Anonymous Access and Group Permission Bug Reports SCM-Manager	2	195	May 22, 2023

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.

Related Topics