[
https://issues.apache.org/jira/browse/OAK-12260?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Joerg Hoh updated OAK-12260:
----------------------------
Description:
We had the situation in AEM, that requests, which are authenticating with a
single use, where blocking like this:
{noformat}
at
java.util.concurrent.Semaphore.acquire([email protected]/Semaphore.java:318)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:262)
at
org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
at
org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
at
org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:234)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
at
org.apache.felix.jaas.boot.ProxyLoginModule.commit(ProxyLoginModule.java:57)
at
javax.security.auth.login.LoginContext.invoke([email protected]/LoginContext.java:750)
at
javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:672)
at
javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:670)
at java.security.AccessController.doPrivileged([email protected]/Native
Method)
at
javax.security.auth.login.LoginContext.invokePriv([email protected]/LoginContext.java:670)
at
javax.security.auth.login.LoginContext.login([email protected]/LoginContext.java:582)
at
org.apache.jackrabbit.oak.core.ContentRepositoryImpl.login(ContentRepositoryImpl.java:170)
at
org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:303)
{noformat}
while one of the requests looked like this:
{noformat}
t
org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:650)
at
org.apache.jackrabbit.oak.composite.CompositeNodeState.compareAgainstBaseState(CompositeNodeState.java:163)
at
org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:51)
at
org.apache.jackrabbit.oak.spi.commit.EditorHook.processCommit(EditorHook.java:54)
at
org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
at
org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
at
org.apache.jackrabbit.oak.composite.CommitHookEnhancer.processCommit(CommitHookEnhancer.java:55)
at
org.apache.jackrabbit.oak.segment.scheduler.Commit.apply(Commit.java:105)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.execute(LockBasedScheduler.java:299)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:270)
at
org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
at
org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
at
org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.cleanupExpired(TokenProviderImpl.java:485)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:242)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
[...]
{noformat}
In this particular case the created login-tokens were not re-used, but instead
every request (from an automation) created a new login-token. Over time some
40k token nodes were accumulated, and it seems that as part of the login it is
tried to cleanup.
While the re-use of an existing login-token should is advised, we cannot
enforce it all ways. For that we need to improve this situation, so
# it's more obvious what's going on. For that I suggest that a warning should
be logged as soon as more than 1k login-tokens were created. This is should be
a noisy log entry, as the problem can be easy avoided by the user.
# We should see if it's possible to run this cleanup process in a more granular
way (or entirely async). Right now the cleanup process tries to remove all
expired tokens, which can lead to large commits. Instead it could just delete
10 expired tokens (and split the actual work across much more requests).
was:
We had the situation in AEM, that requests, which are authenticating with a
single use, where blocking like this:
{noformat}
at
java.util.concurrent.Semaphore.acquire([email protected]/Semaphore.java:318)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:262)
at
org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
at
org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
at
org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:234)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
at
org.apache.felix.jaas.boot.ProxyLoginModule.commit(ProxyLoginModule.java:57)
at
javax.security.auth.login.LoginContext.invoke([email protected]/LoginContext.java:750)
at
javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:672)
at
javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:670)
at java.security.AccessController.doPrivileged([email protected]/Native
Method)
at
javax.security.auth.login.LoginContext.invokePriv([email protected]/LoginContext.java:670)
at
javax.security.auth.login.LoginContext.login([email protected]/LoginContext.java:582)
at
org.apache.jackrabbit.oak.core.ContentRepositoryImpl.login(ContentRepositoryImpl.java:170)
at
org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:303)
{noformat}
while one of the requests looked like this:
{noformat}
t
org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:650)
at
org.apache.jackrabbit.oak.composite.CompositeNodeState.compareAgainstBaseState(CompositeNodeState.java:163)
at
org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:51)
at
org.apache.jackrabbit.oak.spi.commit.EditorHook.processCommit(EditorHook.java:54)
at
org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
at
org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
at
org.apache.jackrabbit.oak.composite.CommitHookEnhancer.processCommit(CommitHookEnhancer.java:55)
at
org.apache.jackrabbit.oak.segment.scheduler.Commit.apply(Commit.java:105)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.execute(LockBasedScheduler.java:299)
at
org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:270)
at
org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
at
org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
at
org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.cleanupExpired(TokenProviderImpl.java:485)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:242)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
at
org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
[...]
{noformat}
In this particular case the created login-tokens were not re-used, but instead
every request (from an automation) created a new login-token. Over time some
40k token nodes were accumulated, and it seems that as part of the login it is
tried to cleanup.
While the re-use of an existing login-token should is advised, we cannot
enforce it all ways. For that we need to improve this situation, so
# it's more obvious what's going on. For that I suggest that a warning should
be logged as soon as more than 1k login-tokens were created. This is should be
a noisy log entry, as the problem can be easy avoided by the user.
# We should see if it's possible to run this cleanup process in an async way.
> TokenLoginModule cannot handle many tokens in a performant way
> --------------------------------------------------------------
>
> Key: OAK-12260
> URL: https://issues.apache.org/jira/browse/OAK-12260
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Components: security
> Affects Versions: 1.80.0
> Reporter: Joerg Hoh
> Priority: Major
>
> We had the situation in AEM, that requests, which are authenticating with a
> single use, where blocking like this:
> {noformat}
> at
> java.util.concurrent.Semaphore.acquire([email protected]/Semaphore.java:318)
> at
> org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:262)
> at
> org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
> at
> org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
> at
> org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:234)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
> at
> org.apache.felix.jaas.boot.ProxyLoginModule.commit(ProxyLoginModule.java:57)
> at
> javax.security.auth.login.LoginContext.invoke([email protected]/LoginContext.java:750)
> at
> javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:672)
> at
> javax.security.auth.login.LoginContext$4.run([email protected]/LoginContext.java:670)
> at
> java.security.AccessController.doPrivileged([email protected]/Native Method)
> at
> javax.security.auth.login.LoginContext.invokePriv([email protected]/LoginContext.java:670)
> at
> javax.security.auth.login.LoginContext.login([email protected]/LoginContext.java:582)
> at
> org.apache.jackrabbit.oak.core.ContentRepositoryImpl.login(ContentRepositoryImpl.java:170)
> at
> org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:303)
> {noformat}
> while one of the requests looked like this:
> {noformat}
> t
> org.apache.jackrabbit.oak.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:650)
> at
> org.apache.jackrabbit.oak.composite.CompositeNodeState.compareAgainstBaseState(CompositeNodeState.java:163)
> at
> org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:51)
> at
> org.apache.jackrabbit.oak.spi.commit.EditorHook.processCommit(EditorHook.java:54)
> at
> org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
> at
> org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:60)
> at
> org.apache.jackrabbit.oak.composite.CommitHookEnhancer.processCommit(CommitHookEnhancer.java:55)
> at
> org.apache.jackrabbit.oak.segment.scheduler.Commit.apply(Commit.java:105)
> at
> org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.execute(LockBasedScheduler.java:299)
> at
> org.apache.jackrabbit.oak.segment.scheduler.LockBasedScheduler.schedule(LockBasedScheduler.java:270)
> at
> org.apache.jackrabbit.oak.segment.SegmentNodeStore.merge(SegmentNodeStore.java:212)
> at
> org.apache.jackrabbit.oak.composite.CompositeNodeStore.merge(CompositeNodeStore.java:152)
> at
> org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:261)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.cleanupExpired(TokenProviderImpl.java:485)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:242)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenProviderImpl.createToken(TokenProviderImpl.java:187)
> at
> org.apache.jackrabbit.oak.security.authentication.token.TokenLoginModule.commit(TokenLoginModule.java:173)
> [...]
> {noformat}
> In this particular case the created login-tokens were not re-used, but
> instead every request (from an automation) created a new login-token. Over
> time some 40k token nodes were accumulated, and it seems that as part of the
> login it is tried to cleanup.
> While the re-use of an existing login-token should is advised, we cannot
> enforce it all ways. For that we need to improve this situation, so
> # it's more obvious what's going on. For that I suggest that a warning should
> be logged as soon as more than 1k login-tokens were created. This is should
> be a noisy log entry, as the problem can be easy avoided by the user.
> # We should see if it's possible to run this cleanup process in a more
> granular way (or entirely async). Right now the cleanup process tries to
> remove all expired tokens, which can lead to large commits. Instead it could
> just delete 10 expired tokens (and split the actual work across much more
> requests).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
