[OAK-5496] Creating service user and setting ACLs immediately for this user fails

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Cannot Reproduce
• Affects Version/s: 1.5.17
• Component/s: core
• Assignee: Unassigned
• Reporter: Oliver Lietz
• Created: 20/Jan/17 12:07
• Updated: 30/Nov/17 20:41
• Resolved: 21/Feb/17 14:02

Description

This error happens only with Mongo, not with Tar. Both Mongo and Tar are affected.

[...]
2017-01-20T11:20:09,185 | DEBUG | Apache Sling Repository Startup Thread | PropertyIndex                    | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | property cost for principalName is 2.0
2017-01-20T11:20:09,185 | DEBUG | Apache Sling Repository Startup Thread | QueryEngineImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | No alternatives found. Query: select [rep:Authorizable].[rep:principalName] as [rep:Authorizable.rep:principalName], [rep:Authorizable].[rep:authorizableId] as [rep:Authorizable.rep:authorizableId], [rep:Authorizable].[jcr:uuid] as [rep:Authorizable.jcr:uuid], [rep:Authorizable].[jcr:primaryType] as [rep:Authorizable.jcr:primaryType], [rep:Authorizable].[jcr:created] as [rep:Authorizable.jcr:created], [rep:Authorizable].[jcr:createdBy] as [rep:Authorizable.jcr:createdBy] from [rep:Authorizable] as [rep:Authorizable] where [rep:Authorizable].[rep:principalName] = $principalName
2017-01-20T11:20:09,186 | DEBUG | Apache Sling Repository Startup Thread | UserManagerImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | System user created: sling-i18n
2017-01-20T11:20:09,186 | INFO  | Apache Sling Repository Startup Thread | AclVisitor                       | 101 - org.apache.sling.jcr.repoinit - 1.1.2 | Adding ACL 'allow' entry '[jcr:read]' for [sling-i18n] on [/]
2017-01-20T11:20:09,187 | DEBUG | Apache Sling Repository Startup Thread | PropertyIndex                    | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | property cost for principalName is 2.0
2017-01-20T11:20:09,187 | DEBUG | Apache Sling Repository Startup Thread | QueryEngineImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | No alternatives found. Query: select [rep:Authorizable].[rep:principalName] as [rep:Authorizable.rep:principalName], [rep:Authorizable].[rep:authorizableId] as [rep:Authorizable.rep:authorizableId], [rep:Authorizable].[jcr:uuid] as [rep:Authorizable.jcr:uuid], [rep:Authorizable].[jcr:primaryType] as [rep:Authorizable.jcr:primaryType], [rep:Authorizable].[jcr:created] as [rep:Authorizable.jcr:created], [rep:Authorizable].[jcr:createdBy] as [rep:Authorizable.jcr:createdBy] from [rep:Authorizable] as [rep:Authorizable] where [rep:Authorizable].[rep:principalName] = $principalName
2017-01-20T11:20:09,187 | DEBUG | Apache Sling Repository Startup Thread | PropertyIndex                    | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | property cost for principalName is 2.0
2017-01-20T11:20:09,188 | DEBUG | Apache Sling Repository Startup Thread | QueryEngineImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | No alternatives found. Query: select [rep:Authorizable].[rep:principalName] as [rep:Authorizable.rep:principalName], [rep:Authorizable].[rep:authorizableId] as [rep:Authorizable.rep:authorizableId], [rep:Authorizable].[jcr:uuid] as [rep:Authorizable.jcr:uuid], [rep:Authorizable].[jcr:primaryType] as [rep:Authorizable.jcr:primaryType], [rep:Authorizable].[jcr:created] as [rep:Authorizable.jcr:created], [rep:Authorizable].[jcr:createdBy] as [rep:Authorizable.jcr:createdBy] from [rep:Authorizable] as [rep:Authorizable] where [rep:Authorizable].[rep:principalName] = $principalName
2017-01-20T11:20:09,188 | DEBUG | Apache Sling Repository Startup Thread | PropertyIndex                    | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | property cost for principalName is 2.0
2017-01-20T11:20:09,188 | DEBUG | Apache Sling Repository Startup Thread | QueryEngineImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | No alternatives found. Query: select [rep:Authorizable].[rep:principalName] as [rep:Authorizable.rep:principalName], [rep:Authorizable].[rep:authorizableId] as [rep:Authorizable.rep:authorizableId], [rep:Authorizable].[jcr:uuid] as [rep:Authorizable.jcr:uuid], [rep:Authorizable].[jcr:primaryType] as [rep:Authorizable.jcr:primaryType], [rep:Authorizable].[jcr:created] as [rep:Authorizable.jcr:created], [rep:Authorizable].[jcr:createdBy] as [rep:Authorizable.jcr:createdBy] from [rep:Authorizable] as [rep:Authorizable] where [rep:Authorizable].[rep:principalName] = $principalName
2017-01-20T11:20:09,189 | DEBUG | Apache Sling Repository Startup Thread | PropertyIndex                    | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | property cost for principalName is 2.0
2017-01-20T11:20:09,189 | DEBUG | Apache Sling Repository Startup Thread | QueryEngineImpl                  | 58 - org.apache.jackrabbit.oak-core - 1.5.17 | No alternatives found. Query: select [rep:Authorizable].[rep:principalName] as [rep:Authorizable.rep:principalName], [rep:Authorizable].[rep:authorizableId] as [rep:Authorizable.rep:authorizableId], [rep:Authorizable].[jcr:uuid] as [rep:Authorizable.jcr:uuid], [rep:Authorizable].[jcr:primaryType] as [rep:Authorizable.jcr:primaryType], [rep:Authorizable].[jcr:created] as [rep:Authorizable.jcr:created], [rep:Authorizable].[jcr:createdBy] as [rep:Authorizable.jcr:createdBy] from [rep:Authorizable] as [rep:Authorizable] where [rep:Authorizable].[rep:principalName] = $principalName
2017-01-20T11:20:09,190 | ERROR | Apache Sling Repository Startup Thread | OakSlingRepositoryManager        | 93 - org.apache.sling.jcr.base - 3.0.0 | Exception in a SlingRepositoryInitializer, SlingRepository service registration aborted
java.lang.RuntimeException: Failed to set ACL (java.lang.IllegalStateException: Principal not found: sling-i18n) AclLine ALLOW {paths=[/], privileges=[jcr:read]}
	at org.apache.sling.jcr.repoinit.impl.AclVisitor.setAcl(AclVisitor.java:61) [101:org.apache.sling.jcr.repoinit:1.1.2]
	at org.apache.sling.jcr.repoinit.impl.AclVisitor.visitSetAclPrincipal(AclVisitor.java:70) [101:org.apache.sling.jcr.repoinit:1.1.2]
	at org.apache.sling.repoinit.parser.operations.SetAclPrincipals.accept(SetAclPrincipals.java:48) [108:org.apache.sling.repoinit.parser:1.1.0]
	at org.apache.sling.jcr.repoinit.impl.JcrRepoInitOpsProcessorImpl.apply(JcrRepoInitOpsProcessorImpl.java:49) [101:org.apache.sling.jcr.repoinit:1.1.2]
	at org.apache.sling.jcr.repoinit.impl.RepositoryInitializer.processRepository(RepositoryInitializer.java:98) [101:org.apache.sling.jcr.repoinit:1.1.2]
	at org.apache.sling.jcr.base.AbstractSlingRepositoryManager.executeRepositoryInitializers(AbstractSlingRepositoryManager.java:541) [93:org.apache.sling.jcr.base:3.0.0]
	at org.apache.sling.jcr.base.AbstractSlingRepositoryManager.initializeAndRegisterRepositoryService(AbstractSlingRepositoryManager.java:485) [93:org.apache.sling.jcr.base:3.0.0]
	at org.apache.sling.jcr.base.AbstractSlingRepositoryManager.access$300(AbstractSlingRepositoryManager.java:85) [93:org.apache.sling.jcr.base:3.0.0]
	at org.apache.sling.jcr.base.AbstractSlingRepositoryManager$4.run(AbstractSlingRepositoryManager.java:455) [93:org.apache.sling.jcr.base:3.0.0]
Caused by: java.lang.IllegalStateException: Principal not found: sling-i18n
	at org.apache.sling.jcr.repoinit.impl.AclUtil.setAcl(AclUtil.java:71) ~[?:?]
	at org.apache.sling.jcr.repoinit.impl.AclVisitor.setAcl(AclVisitor.java:59) ~[?:?]
	... 8 more
[...]

See SLING-6182 "repoinit fails to set ACL on previously created principal" also.

Issue Links

• blocks: SLING-6182 repoinit fails to set ACL on previously created principal
• relates to: OAK-3228 Delayed visibility of new groups when using PrincipalManager
• relates to: SLING-7268 unable to create principals and use principals in ACLs on import