[midPoint] Approval performance issue : slow approverRef for orgs

Thu Oct 24 12:30:31 CEST 2019

Hello Pavol,

Thank you for your input. I want further up in the profiling data (see
attached file) starting at the
...model.impl.lens.Clockwork->authorizeRequest call which I guess is the
start of the authorization process for add the “suborg TEST” organization.

Then I get a bunch of “authorization 'authorization_name' in
dummy:00000000-0000-0000-0000-000000000000(Authorization_rolename) not
applicable for object because of” (from line 4 to 270) but my guess is
these are not an issue.

Then the case “Approving and executing creation of organization "suborg
TEST"” is created (line 360), then I see
...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees#
(line 471) which might be culprit because shortly after that, I see :

2019-10-21 17:22:08,733 DEBUG: ##### Exit: 2255172
...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 16847.160 ms

2019-10-21 17:22:08,865 TRACE: ###### retval:
[user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+
users]

which returned several thousands of user and lasted for more than 16
seconds, and shortly after that (line 809), again another

2019-10-21 17:22:15,333 DEBUG: ##### Exit: 2255170
...repo.cache.RepositoryCache->searchObjects# etime: 23446.578 ms

2019-10-21 17:22:15,510 TRACE: ###### retval:
[user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+
users]

Which lasted for more than 23 seconds. These 3 following lines seems to
confirm that the getDepyutyAssignees is the issue (lines 823 to 827) :

2019-10-21 17:22:16,907 DEBUG: ##### Exit: 2255169
...model.api.ModelInteractionService->getDeputyAssignees etime: 25021.556 ms

2019-10-21 17:22:16,908 TRACE: ###### retval: {}

2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255168
...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees#
etime: 25021.792 ms

2019-10-21 17:22:16,908 TRACE: ###### retval: []

2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255165
...wf.impl.engine.actions.OpenStageAction->execute etime: 25023.855 ms

Is this getDeputyAssignees normal for an approveRef?

-Frederic

On Tue, Oct 22, 2019, 19:04 Pavol Mederly <mederly at evolveum.com> wrote:

> Hello Fréderic,
>
> you are going in the right way. But you need to analyze the profiling data
> in more depth. E.g. it looks like the most interesting part is *before *the
> fragment you sent here.
> Best regards,
>
> Pavol Mederly
> Software developerevolveum.com
>
> On 22.10.2019 18:46, Frédéric Lohier wrote:
>
> Hello,
>
>
>
> I noticed a performance issue with approvals when the approverRef
> references a group of user (Org or Role) in a Midpoint instance with 20000+
> users. My approvals are specified in a globalPolicyRule in the
> SystemConfiguration object.
>
>
>
> When I specifies the approverRef as below, the approval request or the
> approval response each takes up to 30 seconds :
>
>
>
> <approverRef oid="00000000-0000-0000-0000-000000000000"
> relation="org:default" type="c:OrgType">
>
>
>
> Or
>
>
>
> <approverRef type="OrgType">
>
>    <filter>
>
>       <q:equal>
>
>          <q:path>name</q:path>
>
>          <q:value>Name of the org</q:value>
>
>       </q:equal>
>
>    </filter>
>
>    <resolutionTime>run</resolutionTime>
>
>  </approverRef>
>
>
>
> If I reduce the number of users in Midpoint, the approval request/response
> gets faster.
>
>
>
> On the other hand, If I specify a static list of approverRef like :
>
>
>
> <approverRef oid="00000000-0000-0000-0000-000000000000" type="c:UserType">
>
> <approverRef oid="00000000-0000-0000-0000-000000000000" type="c:UserType">
>
>
>
> Or a dynamic list of approvers through an approverExpression like :
>
>
>
> <approverExpression>
>
>     <script>
>
>
> <code>midpoint.getMembersAsReferences("00000000-0000-0000-0000-000000000000")</code>
>
>     </script>
>
> </approverExpression>
>
>
>
> Then , even with 20000+ users, the approval request/response takes less
> than a second to be processed.
>
>
>
> For reference, the full global policy rule :
>
>
>
> <globalPolicyRule>
>
>         <name>Delete user approvals</name>
>
>         <policyConstraints>
>
>             <modification>
>
>                 <operation>delete</operation>
>
>             </modification>
>
>         </policyConstraints>
>
>         <policyActions>
>
>             <approval>
>
>                 <approvalSchema>
>
>                     <stage>
>
>                         <approverRef
> oid="00000000-0000-0000-0000-000000000000" relation="org:default"
> type="c:OrgType">
>
>                         <!-- Administrateurs Identités Arobas -->
>
>                         </approverRef>
>
>                         <automaticallyCompleted>
>
>                             <description>If the user has the superuser
> role, we automatically approve</description>
>
>                             <script>
>
>                                 <code>
>
>                                     if (midpoint.isDirectlyAssigned(actor,
> "00000000-0000-0000-0000-000000000004")) {
>
>                                         return 'skip';
>
>                                     }
>
>                                     else {
>
>                                         return null;
>
>                                     }
>
>                                 </code>
>
>                             </script>
>
>                         </automaticallyCompleted>
>
>                     </stage>
>
>                 </approvalSchema>
>
>             </approval>
>
>         </policyActions>
>
>         <focusSelector>
>
>             <type>UserType</type>
>
>         </focusSelector>
>
>     </globalPolicyRule>
>
>
>
> An excerpt of the trace:
>
>
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255272
> ...repo.cache.RepositoryCache->getObject# etime: 1.311 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval:
> systemConfiguration:00000000-0000-0000-0000-000000000001(SystemConfiguration)
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255271
> ...wf.impl.engine.helpers.NotificationHelper->sendPreparedNotifications
> etime: 1.755 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255257
> ...wf.impl.engine.EngineInvocationContext->commit etime: 40.146 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255157
> ...wf.impl.engine.WorkflowEngine->executeRequest etime: 25067.345 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255136
> ...wf.impl.processors.primary.PrimaryChangeProcessor->executeStartInstructions
> etime: 25146.234 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255118
> ...wf.impl.processors.primary.PrimaryChangeProcessor->previewOrProcessModelInvocation
> etime: 25153.706 ms
>
> 2019-10-21 17:22:16,948 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255117
> ...wf.impl.hook.WfHook->invoke etime: 25153.876 ms
>
> 2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254939
> ...model.impl.lens.Clockwork->click etime: 25198.070 ms
>
> 2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,949 DEBUG: #### Entry: 2255276
> ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache#
>
> 2019-10-21 17:22:16,949 TRACE: ###### args: ()
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255276
> ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache#
> etime: 0.012 ms
>
> 2019-10-21 17:22:16,949 TRACE: ###### retval: null
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254935
> ...model.impl.lens.Clockwork->run etime: 25198.487 ms
>
> 2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254934
> ...model.api.ModelService->executeChanges etime: 25198.728 ms
>
> 2019-10-21 17:22:16,949 TRACE: ###### retval: {}
>
> 2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254933
> ...model.impl.controller.ModelController->executeChanges# etime: 25201.841
> ms
>
>
>
> _______________________________________________
> midPoint mailing listmidPoint at lists.evolveum.comhttp://lists.evolveum.com/mailman/listinfo/midpoint
>
> _______________________________________________
> midPoint mailing list
> midPoint at lists.evolveum.com
> http://lists.evolveum.com/mailman/listinfo/midpoint
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.evolveum.com/pipermail/midpoint/attachments/20191024/e3a3630c/attachment.htm>
-------------- next part --------------
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255058     ...model.impl.lens.Clockwork->authorizeRequest
2019-10-21 17:21:51,791 TRACE: ###### args: ()
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255059      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(8):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 16bb3a1a, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255060       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(8):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 16bb3a1a, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255060        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.036 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: true
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255059       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.107 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: true
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255061      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(9):[PP({.../common/common-3}type):[PPV(QName:ShadowType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 229ad6d5, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self Shadow read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255062       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(9):[PP({.../common/common-3}type):[PPV(QName:ShadowType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 229ad6d5, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self Shadow read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255062        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.042 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: false
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255061       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.098 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: false
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255063      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(10):[PP({.../common/common-3}type):[PPV(QName:UserType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 50d60620, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self persona read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255064       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(10):[PP({.../common/common-3}type):[PPV(QName:UserType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 50d60620, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self persona read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255064        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.037 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: false
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255063       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.099 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: false
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255065      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(11):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 6bf387dd, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Assignment target get' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255066       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(11):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 6bf387dd, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Assignment target get' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255066        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: true
2019-10-21 17:21:51,791 DEBUG: ##### Exit: 2255065       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.091 ms
2019-10-21 17:21:51,791 TRACE: ###### retval: true
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255067      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,791 TRACE: ###### args: (PCV(16):[PP({.../common/common-3}type):[PPV(QName:LookupTableType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 24d71b53, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Lookuptable read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,791 DEBUG: #### Entry: 2255068       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(16):[PP({.../common/common-3}type):[PPV(QName:LookupTableType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 24d71b53, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Lookuptable read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255068        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.037 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255067       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.082 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255069      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:ArchetypeType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 508f5d62, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Archetype read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255070       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:ArchetypeType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 508f5d62, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Archetype read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_User) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255070        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255069       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.074 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255071      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(21):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 3088a655, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255072       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(21):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 3088a655, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255072        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.032 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: true
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255071       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.082 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: true
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255073      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(22):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 473202f6, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User add authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255074       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(22):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 473202f6, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User add authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255074        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.040 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255073       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.085 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255075      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(23):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 5b2384c0, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User delete authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255076       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(23):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 5b2384c0, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User delete authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255076        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255075       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.077 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255077      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(24):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 71eda68b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User items read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255078       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(24):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 71eda68b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User items read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255078        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255077       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.073 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255079      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(25):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4220ced, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User items modify authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255080       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(25):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4220ced, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User items modify authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255080        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.030 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255079       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.071 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255081      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(26):[PP({.../common/common-3}type):[PPV(QName:ShadowType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 53d08b2d, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User shadows read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255082       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(26):[PP({.../common/common-3}type):[PPV(QName:ShadowType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 53d08b2d, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User shadows read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255082        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.034 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255081       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.075 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255083      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(27):[PP({.../common/common-3}type):[PPV(QName:ShadowType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 14920013, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User shadows modify authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255084       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(27):[PP({.../common/common-3}type):[PPV(QName:ShadowType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 14920013, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User shadows modify authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255084        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255083       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.072 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255085      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(28):[PP({.../common/common-3}type):[PPV(QName:RoleType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 8d725f4, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Role read authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255086       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(28):[PP({.../common/common-3}type):[PPV(QName:RoleType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 8d725f4, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Role read authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255086        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.032 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255085       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.073 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255087      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(29):[PP({.../common/common-3}type):[PPV(QName:CaseType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 1c061567, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Case read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255088       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,792 TRACE: ###### args: (PCV(29):[PP({.../common/common-3}type):[PPV(QName:CaseType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 1c061567, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Case read authorizations' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255088        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.030 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: ##### Exit: 2255087       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.076 ms
2019-10-21 17:21:51,792 TRACE: ###### retval: false
2019-10-21 17:21:51,792 DEBUG: #### Entry: 2255089      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(30):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4b587c29, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self owned task read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255090       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(30):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4b587c29, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self owned task read' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255090        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.040 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255089       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.094 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255091      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(31):[PP({.../common/common-3}type):[PPV(QName:TaskType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4f4e6fc9, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'assignment-target-read-task' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255092       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(31):[PP({.../common/common-3}type):[PPV(QName:TaskType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4f4e6fc9, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'assignment-target-read-task' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255092        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255091       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.072 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255093      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(32):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at 534b53b3[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 7e871b51, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255094       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(32):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at 534b53b3[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 7e871b51, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255094        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.075 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255093       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.214 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: false
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255095      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(11):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 520694cb, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization items read authorizations' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255096       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(11):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 520694cb, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization items read authorizations' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255096        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.042 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255095       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.090 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255097      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(12):[PP({.../common/common-3}type):[PPV(QName:OrgType)], PC(orgRelation):[PCV(null):[PP({.../common/common-3}subjectRelation):[PPV(QName:{...common/org-3}manager)], PP({.../common/common-3}scope):[PPV(OrgScopeType:ALL_DESCENDANTS)], PP({.../common/common-3}includeReferenceOrg):[PPV(Boolean:true)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 5ab71396, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization items modify authorizations' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255098       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(12):[PP({.../common/common-3}type):[PPV(QName:OrgType)], PC(orgRelation):[PCV(null):[PP({.../common/common-3}subjectRelation):[PPV(QName:{...common/org-3}manager)], PP({.../common/common-3}scope):[PPV(OrgScopeType:ALL_DESCENDANTS)], PP({.../common/common-3}includeReferenceOrg):[PPV(Boolean:true)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 5ab71396, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization items modify authorizations' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255098        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.046 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255097       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.128 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255099      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(13):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 66bb0f2e, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization add authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255100       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(13):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 66bb0f2e, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization add authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255100        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255099       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.078 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255101      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(14):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 20a0cd3b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization delete authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255102       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(14):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 20a0cd3b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization delete authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255102        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.031 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: ##### Exit: 2255101       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.081 ms
2019-10-21 17:21:51,793 TRACE: ###### retval: true
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255103      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,793 TRACE: ###### args: (PCV(15):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4666a528, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self owned task read' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,793 DEBUG: #### Entry: 2255104       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(15):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4666a528, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Self owned task read' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255104        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.041 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255103       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.094 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255105      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(16):[PP({.../common/common-3}type):[PPV(QName:TaskType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 24af25d1, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'assignment-target-read-task' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255106       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(16):[PP({.../common/common-3}type):[PPV(QName:TaskType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 24af25d1, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'assignment-target-read-task' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255106        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.038 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255105       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.092 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255107      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at a38fd22[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 1ad38c15, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255108       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at a38fd22[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 1ad38c15, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255108        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.067 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255107       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.177 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255109      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(22):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 3c3c5361, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User add authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255110       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(22):[PP({.../common/common-3}type):[PPV(QName:UserType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 3c3c5361, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'User add authorization' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255110        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.035 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255109       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.091 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255111      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(32):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at 534b53b3[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4f00fe2b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255112       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(32):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at 534b53b3[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 4f00fe2b, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in dummy:00000000-0000-0000-0000-000000000000(Midpoint_Identity_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255112        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.065 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255111       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.159 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: false
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255113      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(13):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 125cdbb7, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization add authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255114       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(13):[PP({.../common/common-3}type):[PPV(QName:OrgType)]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 125cdbb7, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'Organization add authorization' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255114        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.032 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: true
2019-10-21 17:21:51,794 DEBUG: ##### Exit: 2255113       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.081 ms
2019-10-21 17:21:51,794 TRACE: ###### retval: true
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255115      ...repo.cache.RepositoryCache->selectorMatches#
2019-10-21 17:21:51,794 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at a38fd22[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 14695ecd, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,794 DEBUG: #### Entry: 2255116       ...repo.sql.SqlRepositoryServiceImpl->selectorMatches#
2019-10-21 17:21:51,795 TRACE: ###### args: (PCV(17):[PP({.../common/common-3}type):[PPV(QName:TaskType)], PP({.../common/common-3}filter):[PPV(SearchFilterType:com.evolveum.prism.xml.ns._public.query_3.SearchFilterType at a38fd22[description=<null>,filterClauseXNode=XNode(map:1 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}equal: XNode(map:2 entries)
E({http://prism.evolveum.com/xml/ns/public/query-3}path: XNode(primitive:handlerUri (class com.evolveum.prism.xml.ns._public.types_3.ItemPathType))); 
E({http://prism.evolveum.com/xml/ns/public/query-3}value: XNode(primitive:parser ValueParser(DOMe, {http://prism.evolveum.com/xml/ns/public/query-3}value: http://midpoint.evolveum.com/xml/ns/public/model/synchronization/task/execute/handler-3))); 
); 
])], PC(owner):[PCV(null):[PP({.../common/common-3}special):[PPV(SpecialObjectSpecificationType:SELF)]]]], org:null(suborg TEST), com.evolveum.midpoint.security.enforcer.impl.SecurityEnforcerImpl$$Lambda$1138/0x000000084183dc40 at 14695ecd, com.evolveum.midpoint.util.logging.impl.TraceImpl at bb764ef,     authorization 'self-owned-task-add-execute-changes' in role:00000000-0000-0000-0000-000000000000(Midpoint_Org_Manager) not applicable for object because of)
2019-10-21 17:21:51,795 DEBUG: ##### Exit: 2255116        ...repo.sql.SqlRepositoryServiceImpl->selectorMatches# etime: 0.072 ms
2019-10-21 17:21:51,795 TRACE: ###### retval: false
2019-10-21 17:21:51,795 DEBUG: ##### Exit: 2255115       ...repo.cache.RepositoryCache->selectorMatches# etime: 0.161 ms
2019-10-21 17:21:51,795 TRACE: ###### retval: false
2019-10-21 17:21:51,795 DEBUG: ##### Exit: 2255058      ...model.impl.lens.Clockwork->authorizeRequest etime: 3.695 ms
2019-10-21 17:21:51,795 TRACE: ###### retval: {}
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255117     ...wf.impl.hook.WfHook->invoke
2019-10-21 17:21:51,795 TRACE: ###### args: ()
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255118      ...wf.impl.processors.primary.PrimaryChangeProcessor->previewOrProcessModelInvocation
2019-10-21 17:21:51,795 TRACE: ###### args: (previewOnly => [false])
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255119       ...wf.impl.processors.primary.PrimaryChangeProcessor->gatherStartInstructions
2019-10-21 17:21:51,795 TRACE: ###### args: ()
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255120        ...wf.impl.processors.primary.policy.PolicyRuleBasedAspect->getStartInstructions
2019-10-21 17:21:51,795 TRACE: ###### args: ()
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255121         ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:21:51,795 TRACE: ###### args: (UserType, a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e, null, R(com.evolveum.midpoint.wf.impl.processors.primary.policy.PolicyRuleBasedAspect.getStartInstructions UNKNOWN null))
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255122          ...repo.cache.RepositoryCache->getObject
2019-10-21 17:21:51,795 TRACE: ###### args: (options => null, oid => [a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#UserType])
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255123           ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:21:51,795 TRACE: ###### args: (UserType, a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.getObject UNKNOWN null))
2019-10-21 17:21:51,795 DEBUG: #### Entry: 2255124            ...repo.api.RepositoryService->getObject
2019-10-21 17:21:51,795 TRACE: ###### args: (oid => [a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.UserType])
2019-10-21 17:21:51,797 DEBUG: ##### Exit: 2255124             ...repo.api.RepositoryService->getObject etime: 2.092 ms
2019-10-21 17:21:51,797 TRACE: ###### retval: {}
2019-10-21 17:21:51,797 DEBUG: ##### Exit: 2255123            ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 2.148 ms
2019-10-21 17:21:51,797 TRACE: ###### retval: dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin)
2019-10-21 17:21:51,797 DEBUG: ##### Exit: 2255122           ...repo.cache.RepositoryCache->getObject etime: 2.373 ms
2019-10-21 17:21:51,797 TRACE: ###### retval: {}
2019-10-21 17:21:51,797 DEBUG: ##### Exit: 2255121          ...repo.cache.RepositoryCache->getObject# etime: 2.413 ms
2019-10-21 17:21:51,797 TRACE: ###### retval: dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin)
2019-10-21 17:21:51,797 DEBUG: #### Entry: 2255125         ...wf.impl.processors.primary.policy.AssignmentPolicyAspectPart->extractAssignmentBasedInstructions
2019-10-21 17:21:51,797 TRACE: ###### args: ()
2019-10-21 17:21:51,797 DEBUG: #### Entry: 2255126          ...repo.cache.RepositoryCache->searchObjects#
2019-10-21 17:21:51,798 TRACE: ###### args: (FocusType, Q{OR(NONE,REF: roleMembershipRef,PRV(oid=ed907172-b46e-45d7-82ca-208d7db192f4, targetType=null, relation={.../common/org-3}approver)),null paging, null, R(com.evolveum.midpoint.wf.impl.processors.primary.policy.AssignmentPolicyAspectPart.extractAssignmentBasedInstructions UNKNOWN null))
2019-10-21 17:21:51,798 DEBUG: #### Entry: 2255127           ...repo.cache.RepositoryCache->searchObjects
2019-10-21 17:21:51,798 TRACE: ###### args: (query => [Q{OR(NONE,REF: roleMembershipRef,PRV(oid=ed907172-b46e-45d7-82ca-208d7db192f4, targetType=null, relation={.../common/org-3}approver)),null paging], options => null, type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#FocusType])
2019-10-21 17:21:51,798 DEBUG: #### Entry: 2255128            ...repo.sql.SqlRepositoryServiceImpl->searchObjects#
2019-10-21 17:21:51,798 TRACE: ###### args: (FocusType, Q{OR(NONE,REF: roleMembershipRef,PRV(oid=ed907172-b46e-45d7-82ca-208d7db192f4, targetType=null, relation={.../common/org-3}approver)),null paging, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.searchObjects UNKNOWN null))
2019-10-21 17:21:51,798 DEBUG: #### Entry: 2255129             ...repo.api.RepositoryService->searchObjects
2019-10-21 17:21:51,798 TRACE: ###### args: (query => [Q{OR(NONE,REF: roleMembershipRef,PRV(oid=ed907172-b46e-45d7-82ca-208d7db192f4, targetType=null, relation={.../common/org-3}approver)),null paging], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.FocusType])
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255129              ...repo.api.RepositoryService->searchObjects etime: 2.107 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: {}
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255128             ...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 2.164 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: []
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255127            ...repo.cache.RepositoryCache->searchObjects etime: 2.264 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: {objectsFound=[0]}
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255126           ...repo.cache.RepositoryCache->searchObjects# etime: 2.324 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: []
2019-10-21 17:21:51,800 DEBUG: #### Entry: 2255130          ...model.impl.controller.ModelInteractionServiceImpl->getCompiledUserProfile#
2019-10-21 17:21:51,800 TRACE: ###### args: (Task(id:1571671311742-0-1, name:null, oid:null), R(com.evolveum.midpoint.wf.impl.processors.primary.policy.AssignmentPolicyAspectPart.extractAssignmentBasedInstructions UNKNOWN null))
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255130           ...model.impl.controller.ModelInteractionServiceImpl->getCompiledUserProfile# etime: 0.035 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: com.evolveum.midpoint.model.api.authentication.CompiledUserProfile at 74da54d1
2019-10-21 17:21:51,800 DEBUG: ##### Exit: 2255125          ...wf.impl.processors.primary.policy.AssignmentPolicyAspectPart->extractAssignmentBasedInstructions etime: 2.624 ms
2019-10-21 17:21:51,800 TRACE: ###### retval: {instructionsCreated=[0]}
2019-10-21 17:21:51,800 DEBUG: #### Entry: 2255131         ...wf.impl.processors.primary.policy.ObjectPolicyAspectPart->extractObjectBasedInstructions
2019-10-21 17:21:51,800 TRACE: ###### args: ()
2019-10-21 17:21:51,801 DEBUG: ##### Exit: 2255131          ...wf.impl.processors.primary.policy.ObjectPolicyAspectPart->extractObjectBasedInstructions etime: 1.438 ms
2019-10-21 17:21:51,801 TRACE: ###### retval: {instructionsCreated=[1]}
2019-10-21 17:21:51,801 DEBUG: ##### Exit: 2255120         ...wf.impl.processors.primary.policy.PolicyRuleBasedAspect->getStartInstructions etime: 6.565 ms
2019-10-21 17:21:51,801 TRACE: ###### retval: {}
2019-10-21 17:21:51,801 DEBUG: ##### Exit: 2255119        ...wf.impl.processors.primary.PrimaryChangeProcessor->gatherStartInstructions etime: 6.611 ms
2019-10-21 17:21:51,801 TRACE: ###### retval: {}
2019-10-21 17:21:51,802 DEBUG: #### Entry: 2255132       ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:21:51,802 TRACE: ###### args: (UserType, a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e, null, R(com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor.previewOrProcessModelInvocation UNKNOWN null))
2019-10-21 17:21:51,802 DEBUG: #### Entry: 2255133        ...repo.cache.RepositoryCache->getObject
2019-10-21 17:21:51,802 TRACE: ###### args: (options => null, oid => [a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#UserType])
2019-10-21 17:21:51,802 DEBUG: ##### Exit: 2255133         ...repo.cache.RepositoryCache->getObject etime: 0.134 ms
2019-10-21 17:21:51,802 TRACE: ###### retval: {}
2019-10-21 17:21:51,802 DEBUG: ##### Exit: 2255132        ...repo.cache.RepositoryCache->getObject# etime: 0.190 ms
2019-10-21 17:21:51,802 TRACE: ###### retval: dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin)
2019-10-21 17:21:51,802 DEBUG: #### Entry: 2255134       ...model.common.expression.evaluator.AbstractValueTransformationExpressionEvaluator->evaluateExpression
2019-10-21 17:21:51,802 TRACE: ###### args: (c:context => [automatic completion expression], c:evaluator => [com.evolveum.midpoint.model.common.expression.script.ScriptExpressionEvaluator])
2019-10-21 17:21:51,802 DEBUG: #### Entry: 2255135        ...model.common.expression.script.ScriptExpression->evaluate
2019-10-21 17:21:51,802 TRACE: ###### args: (c:context => [(new) automatic completion expression])
2019-10-21 17:21:51,802 DEBUG: ##### Exit: 2255135         ...model.common.expression.script.ScriptExpression->evaluate etime: 0.113 ms
2019-10-21 17:21:51,802 TRACE: ###### retval: {}
2019-10-21 17:21:51,802 DEBUG: ##### Exit: 2255134        ...model.common.expression.evaluator.AbstractValueTransformationExpressionEvaluator->evaluateExpression etime: 0.155 ms
2019-10-21 17:21:51,802 TRACE: ###### retval: {}
2019-10-21 17:21:51,802 DEBUG: #### Entry: 2255136       ...wf.impl.processors.primary.PrimaryChangeProcessor->executeStartInstructions
2019-10-21 17:21:51,802 TRACE: ###### args: ()
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255137        ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:21:51,803 TRACE: ###### args: (UserType, a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e, null, R(com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor.executeStartInstructions UNKNOWN null))
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255138         ...repo.cache.RepositoryCache->getObject
2019-10-21 17:21:51,803 TRACE: ###### args: (options => null, oid => [a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#UserType])
2019-10-21 17:21:51,803 DEBUG: ##### Exit: 2255138          ...repo.cache.RepositoryCache->getObject etime: 0.117 ms
2019-10-21 17:21:51,803 TRACE: ###### retval: {}
2019-10-21 17:21:51,803 DEBUG: ##### Exit: 2255137         ...repo.cache.RepositoryCache->getObject# etime: 0.175 ms
2019-10-21 17:21:51,803 TRACE: ###### retval: dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin)
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255139        ...repo.cache.RepositoryCache->addObject#
2019-10-21 17:21:51,803 TRACE: ###### args: (case:null(Approving and executing creation of organization "suborg TEST" (started Oct 21, 2019, 5:21:51 PM)), null, R(com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor.executeStartInstructions UNKNOWN null))
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255140         ...repo.cache.RepositoryCache->addObject
2019-10-21 17:21:51,803 TRACE: ###### args: (options => [null], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255141          ...repo.sql.SqlRepositoryServiceImpl->addObject#
2019-10-21 17:21:51,803 TRACE: ###### args: (case:null(Approving and executing creation of organization "suborg TEST" (started Oct 21, 2019, 5:21:51 PM)), null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.addObject UNKNOWN null))
2019-10-21 17:21:51,803 DEBUG: #### Entry: 2255142           ...repo.api.RepositoryService->addObject
2019-10-21 17:21:51,803 TRACE: ###### args: (options => [RepoAddOptions(overwrite=false,allowUnencryptedValues=false)], object => [case:null(Approving and executing creation of organization "suborg TEST" (started Oct 21, 2019, 5:21:51 PM))])
2019-10-21 17:21:51,804 DEBUG: #### Entry: 2255143            ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:21:51,804 TRACE: ###### args: ()
2019-10-21 17:21:51,804 DEBUG: ##### Exit: 2255143             ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.019 ms
2019-10-21 17:21:51,804 TRACE: ###### retval: null
2019-10-21 17:21:51,840 DEBUG: ##### Exit: 2255142            ...repo.api.RepositoryService->addObject etime: 36.415 ms
2019-10-21 17:21:51,840 TRACE: ###### retval: {}
2019-10-21 17:21:51,840 DEBUG: ##### Exit: 2255141           ...repo.sql.SqlRepositoryServiceImpl->addObject# etime: 36.802 ms
2019-10-21 17:21:51,840 TRACE: ###### retval: 444cf1e6-0a8e-4f35-a7e9-8c5f76fbfac7
2019-10-21 17:21:51,843 DEBUG: #### Entry: 2255144          ...repo.cache.RepositoryCache->invalidateCacheEntries
2019-10-21 17:21:51,843 TRACE: ###### args: (additionalInfo => [AddObjectResult], oid => [444cf1e6-0a8e-4f35-a7e9-8c5f76fbfac7], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,843 DEBUG: ##### Exit: 2255144           ...repo.cache.RepositoryCache->invalidateCacheEntries etime: 0.154 ms
2019-10-21 17:21:51,843 TRACE: ###### retval: {}
2019-10-21 17:21:51,843 DEBUG: ##### Exit: 2255140          ...repo.cache.RepositoryCache->addObject etime: 39.911 ms
2019-10-21 17:21:51,843 TRACE: ###### retval: {}
2019-10-21 17:21:51,843 DEBUG: ##### Exit: 2255139         ...repo.cache.RepositoryCache->addObject# etime: 39.959 ms
2019-10-21 17:21:51,843 TRACE: ###### retval: 444cf1e6-0a8e-4f35-a7e9-8c5f76fbfac7
2019-10-21 17:21:51,843 DEBUG: #### Entry: 2255145        ...repo.cache.RepositoryCache->addObject#
2019-10-21 17:21:51,843 TRACE: ###### args: (case:null(Adding organization "suborg TEST"), null, R(com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor.executeStartInstructions UNKNOWN null))
2019-10-21 17:21:51,843 DEBUG: #### Entry: 2255146         ...repo.cache.RepositoryCache->addObject
2019-10-21 17:21:51,843 TRACE: ###### args: (options => [null], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,843 DEBUG: #### Entry: 2255147          ...repo.sql.SqlRepositoryServiceImpl->addObject#
2019-10-21 17:21:51,844 TRACE: ###### args: (case:null(Adding organization "suborg TEST"), null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.addObject UNKNOWN null))
2019-10-21 17:21:51,844 DEBUG: #### Entry: 2255148           ...repo.api.RepositoryService->addObject
2019-10-21 17:21:51,844 TRACE: ###### args: (options => [RepoAddOptions(overwrite=false,allowUnencryptedValues=false)], object => [case:null(Adding organization "suborg TEST")])
2019-10-21 17:21:51,844 DEBUG: #### Entry: 2255149            ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:21:51,844 TRACE: ###### args: ()
2019-10-21 17:21:51,844 DEBUG: ##### Exit: 2255149             ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.019 ms
2019-10-21 17:21:51,844 TRACE: ###### retval: null
2019-10-21 17:21:51,873 DEBUG: ##### Exit: 2255148            ...repo.api.RepositoryService->addObject etime: 29.452 ms
2019-10-21 17:21:51,873 TRACE: ###### retval: {}
2019-10-21 17:21:51,873 DEBUG: ##### Exit: 2255147           ...repo.sql.SqlRepositoryServiceImpl->addObject# etime: 29.731 ms
2019-10-21 17:21:51,873 TRACE: ###### retval: 9fba6bff-6af2-4cd5-b394-6254c1c79d87
2019-10-21 17:21:51,873 DEBUG: #### Entry: 2255150          ...repo.cache.RepositoryCache->invalidateCacheEntries
2019-10-21 17:21:51,873 TRACE: ###### args: (additionalInfo => [AddObjectResult], oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,873 DEBUG: ##### Exit: 2255150           ...repo.cache.RepositoryCache->invalidateCacheEntries etime: 0.078 ms
2019-10-21 17:21:51,873 TRACE: ###### retval: {}
2019-10-21 17:21:51,873 DEBUG: ##### Exit: 2255146          ...repo.cache.RepositoryCache->addObject etime: 29.909 ms
2019-10-21 17:21:51,873 TRACE: ###### retval: {}
2019-10-21 17:21:51,873 DEBUG: ##### Exit: 2255145         ...repo.cache.RepositoryCache->addObject# etime: 29.965 ms
2019-10-21 17:21:51,873 TRACE: ###### retval: 9fba6bff-6af2-4cd5-b394-6254c1c79d87
2019-10-21 17:21:51,874 DEBUG: #### Entry: 2255151        ...repo.cache.RepositoryCache->modifyObject#
2019-10-21 17:21:51,874 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, [ReferenceDeltaImpl( / {.../common/common-3}prerequisiteRef)], R(com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor.executeStartInstructions UNKNOWN null))
2019-10-21 17:21:51,874 DEBUG: #### Entry: 2255152         ...repo.cache.RepositoryCache->modifyObject
2019-10-21 17:21:51,874 TRACE: ###### args: (options => [null], oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,874 DEBUG: #### Entry: 2255153          ...repo.sql.SqlRepositoryServiceImpl->modifyObject#
2019-10-21 17:21:51,874 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, [ReferenceDeltaImpl( / {.../common/common-3}prerequisiteRef)], null, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.modifyObject UNKNOWN null))
2019-10-21 17:21:51,874 DEBUG: #### Entry: 2255154           ...repo.api.RepositoryService->modifyObject
2019-10-21 17:21:51,874 TRACE: ###### args: (oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.CaseType], modifications => [ReferenceDeltaImpl( / {.../common/common-3}prerequisiteRef)])
2019-10-21 17:21:51,877 DEBUG: #### Entry: 2255155            ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:21:51,877 TRACE: ###### args: ()
2019-10-21 17:21:51,877 DEBUG: ##### Exit: 2255155             ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.038 ms
2019-10-21 17:21:51,877 TRACE: ###### retval: null
2019-10-21 17:21:51,881 DEBUG: ##### Exit: 2255154            ...repo.api.RepositoryService->modifyObject etime: 7.103 ms
2019-10-21 17:21:51,881 TRACE: ###### retval: {}
2019-10-21 17:21:51,881 DEBUG: ##### Exit: 2255153           ...repo.sql.SqlRepositoryServiceImpl->modifyObject# etime: 7.176 ms
2019-10-21 17:21:51,881 TRACE: ###### retval: ModifyObjectResult{objectBefore=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), objectAfter=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), modifications=[ReferenceDeltaImpl( / {.../common/common-3}prerequisiteRef)]}
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255156          ...repo.cache.RepositoryCache->invalidateCacheEntries
2019-10-21 17:21:51,881 TRACE: ###### args: (additionalInfo => [ModifyObjectResult], oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,881 DEBUG: ##### Exit: 2255156           ...repo.cache.RepositoryCache->invalidateCacheEntries etime: 0.067 ms
2019-10-21 17:21:51,881 TRACE: ###### retval: {}
2019-10-21 17:21:51,881 DEBUG: ##### Exit: 2255152          ...repo.cache.RepositoryCache->modifyObject etime: 7.350 ms
2019-10-21 17:21:51,881 TRACE: ###### retval: {}
2019-10-21 17:21:51,881 DEBUG: ##### Exit: 2255151         ...repo.cache.RepositoryCache->modifyObject# etime: 7.420 ms
2019-10-21 17:21:51,881 TRACE: ###### retval: ModifyObjectResult{objectBefore=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), objectAfter=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), modifications=[ReferenceDeltaImpl( / {.../common/common-3}prerequisiteRef)]}
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255157        ...wf.impl.engine.WorkflowEngine->executeRequest
2019-10-21 17:21:51,881 TRACE: ###### args: (request => [OpenCaseRequest{caseOid='9fba6bff-6af2-4cd5-b394-6254c1c79d87', causeInformation=null}], attempt => [1])
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255158         ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:21:51,881 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, null, R(com.evolveum.midpoint.wf.impl.engine.WorkflowEngine.executeRequest UNKNOWN null))
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255159          ...repo.cache.RepositoryCache->getObject
2019-10-21 17:21:51,881 TRACE: ###### args: (options => null, oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255160           ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:21:51,881 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.getObject UNKNOWN null))
2019-10-21 17:21:51,881 DEBUG: #### Entry: 2255161            ...repo.api.RepositoryService->getObject
2019-10-21 17:21:51,881 TRACE: ###### args: (oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.CaseType])
2019-10-21 17:21:51,883 DEBUG: ##### Exit: 2255161             ...repo.api.RepositoryService->getObject etime: 2.233 ms
2019-10-21 17:21:51,883 TRACE: ###### retval: {}
2019-10-21 17:21:51,883 DEBUG: ##### Exit: 2255160            ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 2.294 ms
2019-10-21 17:21:51,883 TRACE: ###### retval: case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST")
2019-10-21 17:21:51,883 DEBUG: ##### Exit: 2255159           ...repo.cache.RepositoryCache->getObject etime: 2.355 ms
2019-10-21 17:21:51,883 TRACE: ###### retval: {}
2019-10-21 17:21:51,883 DEBUG: ##### Exit: 2255158          ...repo.cache.RepositoryCache->getObject# etime: 2.402 ms
2019-10-21 17:21:51,883 TRACE: ###### retval: case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST")
2019-10-21 17:21:51,884 DEBUG: #### Entry: 2255162         ...wf.impl.engine.actions.OpenCaseAction->execute
2019-10-21 17:21:51,884 TRACE: ###### args: ()
2019-10-21 17:21:51,884 DEBUG: #### Entry: 2255163          ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:21:51,884 TRACE: ###### args: (UserType, a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e, null, R(com.evolveum.midpoint.wf.impl.engine.actions.OpenCaseAction.execute UNKNOWN null))
2019-10-21 17:21:51,884 DEBUG: #### Entry: 2255164           ...repo.cache.RepositoryCache->getObject
2019-10-21 17:21:51,884 TRACE: ###### args: (options => null, oid => [a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#UserType])
2019-10-21 17:21:51,884 DEBUG: ##### Exit: 2255164            ...repo.cache.RepositoryCache->getObject etime: 0.139 ms
2019-10-21 17:21:51,884 TRACE: ###### retval: {}
2019-10-21 17:21:51,884 DEBUG: ##### Exit: 2255163           ...repo.cache.RepositoryCache->getObject# etime: 0.181 ms
2019-10-21 17:21:51,884 TRACE: ###### retval: dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin)
2019-10-21 17:21:51,884 DEBUG: ##### Exit: 2255162          ...wf.impl.engine.actions.OpenCaseAction->execute etime: 0.586 ms
2019-10-21 17:21:51,884 TRACE: ###### retval: {}
2019-10-21 17:21:51,884 DEBUG: #### Entry: 2255165         ...wf.impl.engine.actions.OpenStageAction->execute
2019-10-21 17:21:51,884 TRACE: ###### args: ()
2019-10-21 17:21:51,885 DEBUG: #### Entry: 2255166          ...model.common.expression.evaluator.AbstractValueTransformationExpressionEvaluator->evaluateExpression
2019-10-21 17:21:51,885 TRACE: ###### args: (c:context => [automatic completion expression], c:evaluator => [com.evolveum.midpoint.model.common.expression.script.ScriptExpressionEvaluator])
2019-10-21 17:21:51,885 DEBUG: #### Entry: 2255167           ...model.common.expression.script.ScriptExpression->evaluate
2019-10-21 17:21:51,885 TRACE: ###### args: (c:context => [(new) automatic completion expression])
2019-10-21 17:21:51,885 DEBUG: ##### Exit: 2255167            ...model.common.expression.script.ScriptExpression->evaluate etime: 0.159 ms
2019-10-21 17:21:51,885 TRACE: ###### retval: {}
2019-10-21 17:21:51,885 DEBUG: ##### Exit: 2255166           ...model.common.expression.evaluator.AbstractValueTransformationExpressionEvaluator->evaluateExpression etime: 0.207 ms
2019-10-21 17:21:51,885 TRACE: ###### retval: {}
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255168          ...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees#
2019-10-21 17:21:51,886 TRACE: ###### args: (PCV(4):[PP({.../common/common-3}name):[PPV(String:Adding organization "suborg TEST")], PP({.../common/common-3}stageNumber):[PPV(Integer:1)], PP({.../common/common-3}createTimestamp):[PPV(XMLGregorianCalendarImpl:2019-10-21T17:21:51.885+02:00)], PrismReferenceImpl({.../common/common-3}candidateRef):[PRV(oid=88a0e96b-670d-4d3b-99b3-5bacce5c8f87, targetType={.../common/common-3}OrgType, relation={.../common/org-3}default)]], Task(id:1571671311742-0-1, name:null, oid:null), R(com.evolveum.midpoint.wf.impl.engine.actions.OpenStageAction.execute UNKNOWN null))
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255169           ...model.api.ModelInteractionService->getDeputyAssignees
2019-10-21 17:21:51,886 TRACE: ###### args: ()
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255170            ...repo.cache.RepositoryCache->searchObjects#
2019-10-21 17:21:51,886 TRACE: ###### args: (UserType, Q{REF: delegatedRef,,null paging, null, R(com.evolveum.midpoint.model.api.ModelInteractionService.getDeputyAssignees UNKNOWN null))
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255171             ...repo.cache.RepositoryCache->searchObjects
2019-10-21 17:21:51,886 TRACE: ###### args: (query => [Q{REF: delegatedRef,,null paging], options => null, type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#UserType])
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255172              ...repo.sql.SqlRepositoryServiceImpl->searchObjects#
2019-10-21 17:21:51,886 TRACE: ###### args: (UserType, Q{REF: delegatedRef,,null paging, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.searchObjects UNKNOWN null))
2019-10-21 17:21:51,886 DEBUG: #### Entry: 2255173               ...repo.api.RepositoryService->searchObjects
2019-10-21 17:21:51,886 TRACE: ###### args: (query => [Q{REF: delegatedRef,,null paging], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.UserType])
2019-10-21 17:21:52,284 DEBUG: #### Entry: 2255174 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:52,284 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:52,284 DEBUG: ##### Exit: 2255174  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.336 ms
2019-10-21 17:21:52,284 TRACE: ###### retval: Task(id:1571671312284-0-1, name:null, oid:null)
2019-10-21 17:21:52,735 DEBUG: #### Entry: 2255175 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:52,735 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:52,736 DEBUG: ##### Exit: 2255175  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.358 ms
2019-10-21 17:21:52,736 TRACE: ###### retval: Task(id:1571671312735-0-1, name:null, oid:null)
2019-10-21 17:21:53,177 DEBUG: #### Entry: 2255176 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:53,177 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:53,178 DEBUG: ##### Exit: 2255176  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.845 ms
2019-10-21 17:21:53,178 TRACE: ###### retval: Task(id:1571671313177-0-1, name:null, oid:null)
2019-10-21 17:21:53,618 DEBUG: #### Entry: 2255177 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:53,618 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:53,619 DEBUG: ##### Exit: 2255177  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.358 ms
2019-10-21 17:21:53,619 TRACE: ###### retval: Task(id:1571671313618-0-1, name:null, oid:null)
2019-10-21 17:21:54,057 DEBUG: #### Entry: 2255178 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:54,057 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:54,057 DEBUG: ##### Exit: 2255178  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.357 ms
2019-10-21 17:21:54,057 TRACE: ###### retval: Task(id:1571671314057-0-1, name:null, oid:null)
2019-10-21 17:21:54,497 DEBUG: #### Entry: 2255179 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:54,497 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:54,497 DEBUG: ##### Exit: 2255179  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.409 ms
2019-10-21 17:21:54,498 TRACE: ###### retval: Task(id:1571671314497-0-1, name:null, oid:null)
2019-10-21 17:21:54,936 DEBUG: #### Entry: 2255180 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:54,937 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:54,937 DEBUG: ##### Exit: 2255180  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.336 ms
2019-10-21 17:21:54,937 TRACE: ###### retval: Task(id:1571671314937-0-1, name:null, oid:null)
2019-10-21 17:21:55,370 DEBUG: #### Entry: 2255181 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:55,370 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:55,370 DEBUG: ##### Exit: 2255181  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.361 ms
2019-10-21 17:21:55,370 TRACE: ###### retval: Task(id:1571671315370-0-1, name:null, oid:null)
2019-10-21 17:21:55,809 DEBUG: #### Entry: 2255182 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:55,809 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:55,810 DEBUG: ##### Exit: 2255182  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.343 ms
2019-10-21 17:21:55,810 TRACE: ###### retval: Task(id:1571671315809-0-1, name:null, oid:null)
2019-10-21 17:21:56,245 DEBUG: #### Entry: 2255183 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:56,245 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:56,246 DEBUG: ##### Exit: 2255183  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.362 ms
2019-10-21 17:21:56,246 TRACE: ###### retval: Task(id:1571671316245-0-1, name:null, oid:null)
2019-10-21 17:21:56,703 DEBUG: #### Entry: 2255184 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:56,703 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:56,704 DEBUG: ##### Exit: 2255184  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.338 ms
2019-10-21 17:21:56,704 TRACE: ###### retval: Task(id:1571671316703-0-1, name:null, oid:null)
2019-10-21 17:21:57,155 DEBUG: #### Entry: 2255185 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:57,155 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:57,156 DEBUG: ##### Exit: 2255185  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.361 ms
2019-10-21 17:21:57,156 TRACE: ###### retval: Task(id:1571671317155-0-1, name:null, oid:null)
2019-10-21 17:21:57,598 DEBUG: #### Entry: 2255186 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:57,598 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:57,599 DEBUG: ##### Exit: 2255186  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.401 ms
2019-10-21 17:21:57,599 TRACE: ###### retval: Task(id:1571671317598-0-1, name:null, oid:null)
2019-10-21 17:21:58,035 DEBUG: #### Entry: 2255187 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:58,035 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:58,035 DEBUG: ##### Exit: 2255187  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.353 ms
2019-10-21 17:21:58,035 TRACE: ###### retval: Task(id:1571671318035-0-1, name:null, oid:null)
2019-10-21 17:21:58,473 DEBUG: #### Entry: 2255188 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:58,473 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:58,473 DEBUG: ##### Exit: 2255188  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.426 ms
2019-10-21 17:21:58,473 TRACE: ###### retval: Task(id:1571671318473-0-1, name:null, oid:null)
2019-10-21 17:21:58,911 DEBUG: #### Entry: 2255189 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:58,911 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:58,911 DEBUG: ##### Exit: 2255189  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.331 ms
2019-10-21 17:21:58,911 TRACE: ###### retval: Task(id:1571671318911-0-1, name:null, oid:null)
2019-10-21 17:21:59,345 DEBUG: #### Entry: 2255190 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:59,345 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:59,346 DEBUG: ##### Exit: 2255190  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.345 ms
2019-10-21 17:21:59,346 TRACE: ###### retval: Task(id:1571671319345-0-1, name:null, oid:null)
2019-10-21 17:21:59,788 DEBUG: #### Entry: 2255191 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:21:59,788 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:21:59,789 DEBUG: ##### Exit: 2255191  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.343 ms
2019-10-21 17:21:59,789 TRACE: ###### retval: Task(id:1571671319788-0-1, name:null, oid:null)
2019-10-21 17:22:00,221 DEBUG: #### Entry: 2255192 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:00,221 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:00,221 DEBUG: ##### Exit: 2255192  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.365 ms
2019-10-21 17:22:00,221 TRACE: ###### retval: Task(id:1571671320221-0-1, name:null, oid:null)
2019-10-21 17:22:00,654 DEBUG: #### Entry: 2255193 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:00,654 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:00,655 DEBUG: ##### Exit: 2255193  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.331 ms
2019-10-21 17:22:00,655 TRACE: ###### retval: Task(id:1571671320655-0-1, name:null, oid:null)
2019-10-21 17:22:01,109 DEBUG: #### Entry: 2255194 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:01,109 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:01,109 DEBUG: ##### Exit: 2255194  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.374 ms
2019-10-21 17:22:01,109 TRACE: ###### retval: Task(id:1571671321109-0-1, name:null, oid:null)
2019-10-21 17:22:01,546 DEBUG: #### Entry: 2255195 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:01,546 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:01,546 DEBUG: ##### Exit: 2255195  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.365 ms
2019-10-21 17:22:01,546 TRACE: ###### retval: Task(id:1571671321546-0-1, name:null, oid:null)
2019-10-21 17:22:01,649 DEBUG: #### Entry: 2255196    ...task.quartzimpl.cluster.ClusterManager->checkSystemConfigurationChanged
2019-10-21 17:22:01,649 TRACE: ###### args: ()
2019-10-21 17:22:01,649 DEBUG: #### Entry: 2255197     ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:01,649 TRACE: ###### args: (SystemConfigurationType, 00000000-0000-0000-0000-000000000001, [ObjectOperationOptions(/:readOnly)], R(com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager.checkSystemConfigurationChanged UNKNOWN null))
2019-10-21 17:22:01,649 DEBUG: #### Entry: 2255198      ...repo.api.RepositoryService->getObject
2019-10-21 17:22:01,649 TRACE: ###### args: (oid => [00000000-0000-0000-0000-000000000001], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.SystemConfigurationType])
2019-10-21 17:22:01,654 DEBUG: ##### Exit: 2255198       ...repo.api.RepositoryService->getObject etime: 4.457 ms
2019-10-21 17:22:01,654 TRACE: ###### retval: {}
2019-10-21 17:22:01,654 DEBUG: ##### Exit: 2255197      ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 4.583 ms
2019-10-21 17:22:01,654 TRACE: ###### retval: systemConfiguration:00000000-0000-0000-0000-000000000001(SystemConfiguration)
2019-10-21 17:22:01,654 DEBUG: ##### Exit: 2255196     ...task.quartzimpl.cluster.ClusterManager->checkSystemConfigurationChanged etime: 4.732 ms
2019-10-21 17:22:01,654 TRACE: ###### retval: {}
2019-10-21 17:22:01,654 DEBUG: #### Entry: 2255199    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:01,654 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:01,654 DEBUG: #### Entry: 2255200     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:01,654 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:01,655 DEBUG: ##### Exit: 2255200      ...repo.api.RepositoryService->getObject etime: 1.063 ms
2019-10-21 17:22:01,655 TRACE: ###### retval: {}
2019-10-21 17:22:01,655 DEBUG: ##### Exit: 2255199     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.185 ms
2019-10-21 17:22:01,655 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:01,655 DEBUG: #### Entry: 2255201    ...repo.sql.SqlRepositoryServiceImpl->searchObjects#
2019-10-21 17:22:01,655 TRACE: ###### args: (NodeType, null, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:01,655 DEBUG: #### Entry: 2255202     ...repo.api.RepositoryService->searchObjects
2019-10-21 17:22:01,655 TRACE: ###### args: (query => [null], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:01,656 DEBUG: ##### Exit: 2255202      ...repo.api.RepositoryService->searchObjects etime: 1.137 ms
2019-10-21 17:22:01,656 TRACE: ###### retval: {}
2019-10-21 17:22:01,656 DEBUG: ##### Exit: 2255201     ...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 1.210 ms
2019-10-21 17:22:01,656 TRACE: ###### retval: [node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)]
2019-10-21 17:22:01,656 DEBUG: #### Entry: 2255203    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:01,656 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:01,657 DEBUG: #### Entry: 2255204     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:01,657 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:01,658 DEBUG: ##### Exit: 2255204      ...repo.api.RepositoryService->getObject etime: 0.980 ms
2019-10-21 17:22:01,658 TRACE: ###### retval: {}
2019-10-21 17:22:01,658 DEBUG: ##### Exit: 2255203     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.073 ms
2019-10-21 17:22:01,658 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:01,658 DEBUG: #### Entry: 2255205    ...repo.sql.SqlRepositoryServiceImpl->modifyObject#
2019-10-21 17:22:01,658 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, [PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE),PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE),PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE),PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)], R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:01,658 DEBUG: #### Entry: 2255206     ...repo.api.RepositoryService->modifyObject
2019-10-21 17:22:01,658 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType], modifications => [PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE), PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE), PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE), PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)])
2019-10-21 17:22:01,659 DEBUG: #### Entry: 2255207      ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:22:01,659 TRACE: ###### args: ()
2019-10-21 17:22:01,659 DEBUG: ##### Exit: 2255207       ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.041 ms
2019-10-21 17:22:01,659 TRACE: ###### retval: null
2019-10-21 17:22:01,661 DEBUG: ##### Exit: 2255206      ...repo.api.RepositoryService->modifyObject etime: 3.177 ms
2019-10-21 17:22:01,661 TRACE: ###### retval: {}
2019-10-21 17:22:01,661 DEBUG: ##### Exit: 2255205     ...repo.sql.SqlRepositoryServiceImpl->modifyObject# etime: 3.313 ms
2019-10-21 17:22:01,661 TRACE: ###### retval: ModifyObjectResult{objectBefore=node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode), objectAfter=node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode), modifications=[PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE), PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE), PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE), PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)]}
2019-10-21 17:22:01,661 DEBUG: #### Entry: 2255208    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:01,661 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:01,661 DEBUG: #### Entry: 2255209     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:01,662 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:01,662 DEBUG: ##### Exit: 2255209      ...repo.api.RepositoryService->getObject etime: 0.942 ms
2019-10-21 17:22:01,662 TRACE: ###### retval: {}
2019-10-21 17:22:01,662 DEBUG: ##### Exit: 2255208     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.002 ms
2019-10-21 17:22:01,662 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:01,983 DEBUG: #### Entry: 2255210 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:01,983 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:01,983 DEBUG: ##### Exit: 2255210  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.362 ms
2019-10-21 17:22:01,983 TRACE: ###### retval: Task(id:1571671321983-0-1, name:null, oid:null)
2019-10-21 17:22:02,419 DEBUG: #### Entry: 2255211 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:02,419 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:02,419 DEBUG: ##### Exit: 2255211  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.329 ms
2019-10-21 17:22:02,419 TRACE: ###### retval: Task(id:1571671322419-0-1, name:null, oid:null)
2019-10-21 17:22:02,855 DEBUG: #### Entry: 2255212 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:02,855 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:02,855 DEBUG: ##### Exit: 2255212  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.352 ms
2019-10-21 17:22:02,855 TRACE: ###### retval: Task(id:1571671322855-0-1, name:null, oid:null)
2019-10-21 17:22:03,287 DEBUG: #### Entry: 2255213 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:03,287 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:03,287 DEBUG: ##### Exit: 2255213  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.329 ms
2019-10-21 17:22:03,287 TRACE: ###### retval: Task(id:1571671323287-0-1, name:null, oid:null)
2019-10-21 17:22:03,729 DEBUG: #### Entry: 2255214 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:03,729 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:03,729 DEBUG: ##### Exit: 2255214  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.350 ms
2019-10-21 17:22:03,729 TRACE: ###### retval: Task(id:1571671323729-0-1, name:null, oid:null)
2019-10-21 17:22:04,167 DEBUG: #### Entry: 2255215 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:04,168 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:04,168 DEBUG: ##### Exit: 2255215  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.356 ms
2019-10-21 17:22:04,168 TRACE: ###### retval: Task(id:1571671324168-0-1, name:null, oid:null)
2019-10-21 17:22:04,595 DEBUG: #### Entry: 2255216 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:04,595 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:04,595 DEBUG: ##### Exit: 2255216  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.318 ms
2019-10-21 17:22:04,595 TRACE: ###### retval: Task(id:1571671324595-0-1, name:null, oid:null)
2019-10-21 17:22:05,028 DEBUG: #### Entry: 2255217 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:05,028 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:05,028 DEBUG: ##### Exit: 2255217  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.337 ms
2019-10-21 17:22:05,028 TRACE: ###### retval: Task(id:1571671325028-0-1, name:null, oid:null)
2019-10-21 17:22:05,463 DEBUG: #### Entry: 2255218 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:05,463 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:05,463 DEBUG: ##### Exit: 2255218  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.346 ms
2019-10-21 17:22:05,463 TRACE: ###### retval: Task(id:1571671325463-0-1, name:null, oid:null)
2019-10-21 17:22:05,898 DEBUG: #### Entry: 2255219 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:05,898 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:05,898 DEBUG: ##### Exit: 2255219  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.353 ms
2019-10-21 17:22:05,898 TRACE: ###### retval: Task(id:1571671325898-0-1, name:null, oid:null)
2019-10-21 17:22:06,333 DEBUG: #### Entry: 2255220 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:06,333 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:06,333 DEBUG: ##### Exit: 2255220  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.348 ms
2019-10-21 17:22:06,333 TRACE: ###### retval: Task(id:1571671326333-0-1, name:null, oid:null)
2019-10-21 17:22:06,767 DEBUG: #### Entry: 2255221 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:06,767 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:06,768 DEBUG: ##### Exit: 2255221  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.332 ms
2019-10-21 17:22:06,768 TRACE: ###### retval: Task(id:1571671326767-0-1, name:null, oid:null)
2019-10-21 17:22:07,201 DEBUG: #### Entry: 2255222 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:07,201 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:07,201 DEBUG: ##### Exit: 2255222  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.357 ms
2019-10-21 17:22:07,201 TRACE: ###### retval: Task(id:1571671327201-0-1, name:null, oid:null)
2019-10-21 17:22:07,665 DEBUG: #### Entry: 2255223 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:07,665 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:07,666 DEBUG: ##### Exit: 2255223  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.365 ms
2019-10-21 17:22:07,666 TRACE: ###### retval: Task(id:1571671327665-0-1, name:null, oid:null)
2019-10-21 17:22:08,099 DEBUG: #### Entry: 2255224 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:08,099 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:08,099 DEBUG: ##### Exit: 2255224  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.348 ms
2019-10-21 17:22:08,099 TRACE: ###### retval: Task(id:1571671328099-0-1, name:null, oid:null)
2019-10-21 17:22:08,539 DEBUG: #### Entry: 2255225 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:08,539 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:08,539 DEBUG: ##### Exit: 2255225  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.335 ms
2019-10-21 17:22:08,539 TRACE: ###### retval: Task(id:1571671328539-0-1, name:null, oid:null)
2019-10-21 17:22:08,733 DEBUG: ##### Exit: 2255173                ...repo.api.RepositoryService->searchObjects etime: 16846.733 ms
2019-10-21 17:22:08,733 TRACE: ###### retval: {}
2019-10-21 17:22:08,733 DEBUG: ##### Exit: 2255172               ...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 16847.160 ms
2019-10-21 17:22:08,865 TRACE: ###### retval: [user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+ users]
2019-10-21 17:22:08,973 DEBUG: #### Entry: 2255226 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:08,973 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:08,973 DEBUG: ##### Exit: 2255226  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.346 ms
2019-10-21 17:22:08,973 TRACE: ###### retval: Task(id:1571671328973-0-1, name:null, oid:null)
2019-10-21 17:22:09,498 DEBUG: #### Entry: 2255227 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:09,498 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:09,498 DEBUG: ##### Exit: 2255227  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.359 ms
2019-10-21 17:22:09,498 TRACE: ###### retval: Task(id:1571671329498-0-1, name:null, oid:null)
2019-10-21 17:22:09,931 DEBUG: #### Entry: 2255228 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:09,931 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:09,931 DEBUG: ##### Exit: 2255228  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.364 ms
2019-10-21 17:22:09,931 TRACE: ###### retval: Task(id:1571671329931-0-1, name:null, oid:null)
2019-10-21 17:22:10,566 DEBUG: #### Entry: 2255229 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:10,566 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:10,567 DEBUG: ##### Exit: 2255229  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.350 ms
2019-10-21 17:22:10,567 TRACE: ###### retval: Task(id:1571671330566-0-1, name:null, oid:null)
2019-10-21 17:22:11,010 DEBUG: #### Entry: 2255230 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:11,010 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:11,011 DEBUG: ##### Exit: 2255230  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.378 ms
2019-10-21 17:22:11,011 TRACE: ###### retval: Task(id:1571671331010-0-1, name:null, oid:null)
2019-10-21 17:22:11,462 DEBUG: #### Entry: 2255231 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:11,462 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:11,462 DEBUG: ##### Exit: 2255231  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.368 ms
2019-10-21 17:22:11,462 TRACE: ###### retval: Task(id:1571671331462-0-1, name:null, oid:null)
2019-10-21 17:22:11,663 DEBUG: #### Entry: 2255232    ...task.quartzimpl.cluster.ClusterManager->checkSystemConfigurationChanged
2019-10-21 17:22:11,663 TRACE: ###### args: ()
2019-10-21 17:22:11,663 DEBUG: #### Entry: 2255233     ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:11,663 TRACE: ###### args: (SystemConfigurationType, 00000000-0000-0000-0000-000000000001, [ObjectOperationOptions(/:readOnly)], R(com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager.checkSystemConfigurationChanged UNKNOWN null))
2019-10-21 17:22:11,663 DEBUG: #### Entry: 2255234      ...repo.api.RepositoryService->getObject
2019-10-21 17:22:11,663 TRACE: ###### args: (oid => [00000000-0000-0000-0000-000000000001], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.SystemConfigurationType])
2019-10-21 17:22:11,668 DEBUG: ##### Exit: 2255234       ...repo.api.RepositoryService->getObject etime: 4.747 ms
2019-10-21 17:22:11,668 TRACE: ###### retval: {}
2019-10-21 17:22:11,668 DEBUG: ##### Exit: 2255233      ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 4.899 ms
2019-10-21 17:22:11,668 TRACE: ###### retval: systemConfiguration:00000000-0000-0000-0000-000000000001(SystemConfiguration)
2019-10-21 17:22:11,668 DEBUG: ##### Exit: 2255232     ...task.quartzimpl.cluster.ClusterManager->checkSystemConfigurationChanged etime: 5.059 ms
2019-10-21 17:22:11,668 TRACE: ###### retval: {}
2019-10-21 17:22:11,668 DEBUG: #### Entry: 2255235    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:11,668 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:11,668 DEBUG: #### Entry: 2255236     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:11,668 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:11,669 DEBUG: ##### Exit: 2255236      ...repo.api.RepositoryService->getObject etime: 1.166 ms
2019-10-21 17:22:11,669 TRACE: ###### retval: {}
2019-10-21 17:22:11,669 DEBUG: ##### Exit: 2255235     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.247 ms
2019-10-21 17:22:11,669 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:11,669 DEBUG: #### Entry: 2255237    ...repo.sql.SqlRepositoryServiceImpl->searchObjects#
2019-10-21 17:22:11,669 TRACE: ###### args: (NodeType, null, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:11,669 DEBUG: #### Entry: 2255238     ...repo.api.RepositoryService->searchObjects
2019-10-21 17:22:11,669 TRACE: ###### args: (query => [null], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:11,670 DEBUG: ##### Exit: 2255238      ...repo.api.RepositoryService->searchObjects etime: 0.971 ms
2019-10-21 17:22:11,670 TRACE: ###### retval: {}
2019-10-21 17:22:11,670 DEBUG: ##### Exit: 2255237     ...repo.sql.SqlRepositoryServiceImpl->searchObjects# etime: 1.050 ms
2019-10-21 17:22:11,670 TRACE: ###### retval: [node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)]
2019-10-21 17:22:11,671 DEBUG: #### Entry: 2255239    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:11,671 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:11,671 DEBUG: #### Entry: 2255240     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:11,671 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:11,672 DEBUG: ##### Exit: 2255240      ...repo.api.RepositoryService->getObject etime: 1.015 ms
2019-10-21 17:22:11,672 TRACE: ###### retval: {}
2019-10-21 17:22:11,672 DEBUG: ##### Exit: 2255239     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.090 ms
2019-10-21 17:22:11,672 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:11,672 DEBUG: #### Entry: 2255241    ...repo.sql.SqlRepositoryServiceImpl->modifyObject#
2019-10-21 17:22:11,672 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, [PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE),PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE),PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE),PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)], R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:11,672 DEBUG: #### Entry: 2255242     ...repo.api.RepositoryService->modifyObject
2019-10-21 17:22:11,672 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType], modifications => [PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE), PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE), PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE), PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)])
2019-10-21 17:22:11,673 DEBUG: #### Entry: 2255243      ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:22:11,673 TRACE: ###### args: ()
2019-10-21 17:22:11,673 DEBUG: ##### Exit: 2255243       ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.030 ms
2019-10-21 17:22:11,673 TRACE: ###### retval: null
2019-10-21 17:22:11,676 DEBUG: ##### Exit: 2255242      ...repo.api.RepositoryService->modifyObject etime: 3.233 ms
2019-10-21 17:22:11,676 TRACE: ###### retval: {}
2019-10-21 17:22:11,676 DEBUG: ##### Exit: 2255241     ...repo.sql.SqlRepositoryServiceImpl->modifyObject# etime: 3.424 ms
2019-10-21 17:22:11,676 TRACE: ###### retval: ModifyObjectResult{objectBefore=node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode), objectAfter=node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode), modifications=[PropertyDeltaImpl( / {.../common/common-3}hostname, REPLACE), PropertyDeltaImpl( / {.../common/common-3}ipAddress, REPLACE), PropertyDeltaImpl( / {.../common/common-3}lastCheckInTime, REPLACE), PropertyDeltaImpl( / {.../common/common-3}url, REPLACE)]}
2019-10-21 17:22:11,676 DEBUG: #### Entry: 2255244    ...repo.sql.SqlRepositoryServiceImpl->getObject#
2019-10-21 17:22:11,676 TRACE: ###### args: (NodeType, 06328afa-ce04-4b52-99a3-958ad38fb231, null, R(class com.evolveum.midpoint.task.quartzimpl.cluster.ClusterManager$ClusterManagerThread.run UNKNOWN null))
2019-10-21 17:22:11,676 DEBUG: #### Entry: 2255245     ...repo.api.RepositoryService->getObject
2019-10-21 17:22:11,676 TRACE: ###### args: (oid => [06328afa-ce04-4b52-99a3-958ad38fb231], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.NodeType])
2019-10-21 17:22:11,677 DEBUG: ##### Exit: 2255245      ...repo.api.RepositoryService->getObject etime: 1.303 ms
2019-10-21 17:22:11,677 TRACE: ###### retval: {}
2019-10-21 17:22:11,677 DEBUG: ##### Exit: 2255244     ...repo.sql.SqlRepositoryServiceImpl->getObject# etime: 1.371 ms
2019-10-21 17:22:11,677 TRACE: ###### retval: node:06328afa-ce04-4b52-99a3-958ad38fb231(DefaultNode)
2019-10-21 17:22:12,066 DEBUG: #### Entry: 2255246 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:12,066 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:12,067 DEBUG: ##### Exit: 2255246  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.330 ms
2019-10-21 17:22:12,067 TRACE: ###### retval: Task(id:1571671332066-0-1, name:null, oid:null)
2019-10-21 17:22:12,503 DEBUG: #### Entry: 2255247 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:12,503 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:12,504 DEBUG: ##### Exit: 2255247  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.360 ms
2019-10-21 17:22:12,504 TRACE: ###### retval: Task(id:1571671332503-0-1, name:null, oid:null)
2019-10-21 17:22:12,941 DEBUG: #### Entry: 2255248 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:12,941 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:12,941 DEBUG: ##### Exit: 2255248  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.350 ms
2019-10-21 17:22:12,941 TRACE: ###### retval: Task(id:1571671332941-0-1, name:null, oid:null)
2019-10-21 17:22:13,374 DEBUG: #### Entry: 2255249 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:13,374 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:13,375 DEBUG: ##### Exit: 2255249  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.318 ms
2019-10-21 17:22:13,375 TRACE: ###### retval: Task(id:1571671333374-0-1, name:null, oid:null)
2019-10-21 17:22:13,810 DEBUG: #### Entry: 2255250 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:13,810 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:13,811 DEBUG: ##### Exit: 2255250  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.323 ms
2019-10-21 17:22:13,811 TRACE: ###### retval: Task(id:1571671333810-0-1, name:null, oid:null)
2019-10-21 17:22:14,249 DEBUG: #### Entry: 2255251 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:14,249 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:14,250 DEBUG: ##### Exit: 2255251  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.293 ms
2019-10-21 17:22:14,250 TRACE: ###### retval: Task(id:1571671334249-0-1, name:null, oid:null)
2019-10-21 17:22:14,684 DEBUG: #### Entry: 2255252 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:14,684 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:14,684 DEBUG: ##### Exit: 2255252  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.325 ms
2019-10-21 17:22:14,684 TRACE: ###### retval: Task(id:1571671334684-0-1, name:null, oid:null)
2019-10-21 17:22:15,248 DEBUG: #### Entry: 2255253 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:15,248 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:15,248 DEBUG: ##### Exit: 2255253  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.313 ms
2019-10-21 17:22:15,248 TRACE: ###### retval: Task(id:1571671335248-0-1, name:null, oid:null)
2019-10-21 17:22:15,333 DEBUG: ##### Exit: 2255171              ...repo.cache.RepositoryCache->searchObjects etime: 23446.445 ms
2019-10-21 17:22:15,333 TRACE: ###### retval: {objectsFound=[26219]}
2019-10-21 17:22:15,333 DEBUG: ##### Exit: 2255170             ...repo.cache.RepositoryCache->searchObjects# etime: 23446.578 ms
2019-10-21 17:22:15,510 TRACE: ###### retval: [user:00000000-0000-0000-0000-000000000000(name),user:00000000-0000-0000-0000-000000000000(name)...26000+ users]
2019-10-21 17:22:15,703 DEBUG: #### Entry: 2255254 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:15,703 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:15,704 DEBUG: ##### Exit: 2255254  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.326 ms
2019-10-21 17:22:15,704 TRACE: ###### retval: Task(id:1571671335703-0-1, name:null, oid:null)
2019-10-21 17:22:16,145 DEBUG: #### Entry: 2255255 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:16,146 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:16,146 DEBUG: ##### Exit: 2255255  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.353 ms
2019-10-21 17:22:16,146 TRACE: ###### retval: Task(id:1571671336146-0-1, name:null, oid:null)
2019-10-21 17:22:16,588 DEBUG: #### Entry: 2255256 ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance#
2019-10-21 17:22:16,588 TRACE: ###### args: (com.evolveum.midpoint.web.security.MidPointGuiAuthorizationEvaluator.decide)
2019-10-21 17:22:16,588 DEBUG: ##### Exit: 2255256  ...task.quartzimpl.TaskManagerQuartzImpl->createTaskInstance# etime: 0.353 ms
2019-10-21 17:22:16,588 TRACE: ###### retval: Task(id:1571671336588-0-1, name:null, oid:null)
2019-10-21 17:22:16,907 DEBUG: ##### Exit: 2255169            ...model.api.ModelInteractionService->getDeputyAssignees etime: 25021.556 ms
2019-10-21 17:22:16,908 TRACE: ###### retval: {}
2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255168           ...model.impl.controller.ModelInteractionServiceImpl->getDeputyAssignees# etime: 25021.792 ms
2019-10-21 17:22:16,908 TRACE: ###### retval: []
2019-10-21 17:22:16,908 DEBUG: ##### Exit: 2255165          ...wf.impl.engine.actions.OpenStageAction->execute etime: 25023.855 ms
2019-10-21 17:22:16,908 TRACE: ###### retval: {}
2019-10-21 17:22:16,908 DEBUG: #### Entry: 2255257         ...wf.impl.engine.EngineInvocationContext->commit
2019-10-21 17:22:16,908 TRACE: ###### args: ()
2019-10-21 17:22:16,911 DEBUG: #### Entry: 2255258          ...repo.cache.RepositoryCache->modifyObject#
2019-10-21 17:22:16,911 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, [PropertyDeltaImpl( / {.../common/common-3}state, REPLACE),PropertyDeltaImpl( / {.../common/common-3}stageNumber, ADD),ContainerDeltaImpl( / {.../common/common-3}workItem, ADD)], com.evolveum.midpoint.repo.api.VersionPrecondition at 44e902e9, null, R(com.evolveum.midpoint.wf.impl.engine.EngineInvocationContext.commit UNKNOWN null))
2019-10-21 17:22:16,911 DEBUG: #### Entry: 2255259           ...repo.cache.RepositoryCache->modifyObject
2019-10-21 17:22:16,911 TRACE: ###### args: (options => [null], oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:22:16,911 DEBUG: #### Entry: 2255260            ...repo.sql.SqlRepositoryServiceImpl->modifyObject#
2019-10-21 17:22:16,911 TRACE: ###### args: (CaseType, 9fba6bff-6af2-4cd5-b394-6254c1c79d87, [PropertyDeltaImpl( / {.../common/common-3}state, REPLACE),PropertyDeltaImpl( / {.../common/common-3}stageNumber, ADD),ContainerDeltaImpl( / {.../common/common-3}workItem, ADD)], com.evolveum.midpoint.repo.api.VersionPrecondition at 44e902e9, null, R(com.evolveum.midpoint.repo.cache.RepositoryCache.modifyObject UNKNOWN null))
2019-10-21 17:22:16,911 DEBUG: #### Entry: 2255261             ...repo.api.RepositoryService->modifyObject
2019-10-21 17:22:16,911 TRACE: ###### args: (oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.CaseType], modifications => [PropertyDeltaImpl( / {.../common/common-3}state, REPLACE), PropertyDeltaImpl( / {.../common/common-3}stageNumber, ADD), ContainerDeltaImpl( / {.../common/common-3}workItem, ADD)])
2019-10-21 17:22:16,916 DEBUG: #### Entry: 2255262              ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration#
2019-10-21 17:22:16,916 TRACE: ###### args: ()
2019-10-21 17:22:16,916 DEBUG: ##### Exit: 2255262               ...repo.sql.SqlRepositoryServiceImpl->getFullTextSearchConfiguration# etime: 0.048 ms
2019-10-21 17:22:16,916 TRACE: ###### retval: null
2019-10-21 17:22:16,936 DEBUG: ##### Exit: 2255261              ...repo.api.RepositoryService->modifyObject etime: 24.949 ms
2019-10-21 17:22:16,936 TRACE: ###### retval: {}
2019-10-21 17:22:16,936 DEBUG: ##### Exit: 2255260             ...repo.sql.SqlRepositoryServiceImpl->modifyObject# etime: 25.081 ms
2019-10-21 17:22:16,936 TRACE: ###### retval: ModifyObjectResult{objectBefore=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), objectAfter=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), modifications=[PropertyDeltaImpl( / {.../common/common-3}state, REPLACE), PropertyDeltaImpl( / {.../common/common-3}stageNumber, ADD), ContainerDeltaImpl( / {.../common/common-3}workItem, ADD)]}
2019-10-21 17:22:16,936 DEBUG: #### Entry: 2255263            ...repo.cache.RepositoryCache->invalidateCacheEntries
2019-10-21 17:22:16,936 TRACE: ###### args: (additionalInfo => [ModifyObjectResult], oid => [9fba6bff-6af2-4cd5-b394-6254c1c79d87], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#CaseType])
2019-10-21 17:22:16,936 DEBUG: ##### Exit: 2255263             ...repo.cache.RepositoryCache->invalidateCacheEntries etime: 0.079 ms
2019-10-21 17:22:16,936 TRACE: ###### retval: {}
2019-10-21 17:22:16,936 DEBUG: ##### Exit: 2255259            ...repo.cache.RepositoryCache->modifyObject etime: 25.295 ms
2019-10-21 17:22:16,936 TRACE: ###### retval: {}
2019-10-21 17:22:16,936 DEBUG: ##### Exit: 2255258           ...repo.cache.RepositoryCache->modifyObject# etime: 25.411 ms
2019-10-21 17:22:16,936 TRACE: ###### retval: ModifyObjectResult{objectBefore=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), objectAfter=case:9fba6bff-6af2-4cd5-b394-6254c1c79d87(Adding organization "suborg TEST"), modifications=[PropertyDeltaImpl( / {.../common/common-3}state, REPLACE), PropertyDeltaImpl( / {.../common/common-3}stageNumber, ADD), ContainerDeltaImpl( / {.../common/common-3}workItem, ADD)]}
2019-10-21 17:22:16,937 DEBUG: #### Entry: 2255264          ...model.impl.util.AuditHelper->resolveName
2019-10-21 17:22:16,937 TRACE: ###### args: ()
2019-10-21 17:22:16,937 DEBUG: #### Entry: 2255265           ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:22:16,937 TRACE: ###### args: (OrgType, ed907172-b46e-45d7-82ca-208d7db192f4, [ObjectOperationOptions(:allowNotFound)], R(com.evolveum.midpoint.model.impl.util.AuditHelper.resolveName UNKNOWN null))
2019-10-21 17:22:16,937 DEBUG: #### Entry: 2255266            ...repo.cache.RepositoryCache->getObject
2019-10-21 17:22:16,937 TRACE: ###### args: (options => [ObjectOperationOptions(:allowNotFound)], oid => [ed907172-b46e-45d7-82ca-208d7db192f4], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#OrgType])
2019-10-21 17:22:16,937 DEBUG: ##### Exit: 2255266             ...repo.cache.RepositoryCache->getObject etime: 0.150 ms
2019-10-21 17:22:16,937 TRACE: ###### retval: {}
2019-10-21 17:22:16,937 DEBUG: ##### Exit: 2255265            ...repo.cache.RepositoryCache->getObject# etime: 0.217 ms
2019-10-21 17:22:16,937 TRACE: ###### retval: org:ed907172-b46e-45d7-82ca-208d7db192f4(subtest3)
2019-10-21 17:22:16,937 DEBUG: ##### Exit: 2255264           ...model.impl.util.AuditHelper->resolveName etime: 0.278 ms
2019-10-21 17:22:16,937 TRACE: ###### retval: {}
2019-10-21 17:22:16,937 DEBUG: #### Entry: 2255267          ...init.AuditServiceProxy->audit#
2019-10-21 17:22:16,937 TRACE: ###### args: (AUDIT[null eid=null sid=null, rid=null, tid=null toid=null, hid=null, nid=null, raddr=null, I=dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin), A=null, T=org:98ab9f46-c578-407d-abf3-af5d07d980f4(suborg TEST), TO=null, et=WORKFLOW_PROCESS_INSTANCE, es=REQUEST, D=[ObjectDeltaOperation(ObjectDelta(OrgType:null,ADD: dummy:98ab9f46-c578-407d-abf3-af5d07d980f4(suborg TEST)): null)], ch=null, o=SUCCESS, r=null, p=null, m=null, cuscolprop={}, prop={wf.processInstanceId=[9fba6bff-6af2-4cd5-b394-6254c1c79d87]}, roid=[], ref={wf.object=[AuditObjectReference{oid='98ab9f46-c578-407d-abf3-af5d07d980f4', type={http://midpoint.evolveum.com/xml/ns/public/common/common-3}OrgType, targetName='suborg TEST'}]}], Task(id:1571671311742-0-1, name:null, oid:null))
2019-10-21 17:22:16,937 DEBUG: #### Entry: 2255268           ...task.quartzimpl.TaskManagerQuartzImpl->getNodeId#
2019-10-21 17:22:16,937 TRACE: ###### args: ()
2019-10-21 17:22:16,937 DEBUG: ##### Exit: 2255268            ...task.quartzimpl.TaskManagerQuartzImpl->getNodeId# etime: 0.009 ms
2019-10-21 17:22:16,937 TRACE: ###### retval: DefaultNode
2019-10-21 17:22:16,942 DEBUG: ##### Exit: 2255267           ...init.AuditServiceProxy->audit# etime: 4.849 ms
2019-10-21 17:22:16,942 TRACE: ###### retval: null
2019-10-21 17:22:16,942 DEBUG: #### Entry: 2255269          ...init.AuditServiceProxy->audit#
2019-10-21 17:22:16,942 TRACE: ###### args: (AUDIT[null eid=null sid=null, rid=null, tid=null toid=null, hid=null, nid=null, raddr=null, I=dummy:a5d60579-c4e4-4a5f-ae7a-7b32f4fbc84e(identityadmin), A=null, T=org:98ab9f46-c578-407d-abf3-af5d07d980f4(suborg TEST), TO=null, et=WORK_ITEM, es=REQUEST, D=[ObjectDeltaOperation(ObjectDelta(OrgType:null,ADD: dummy:98ab9f46-c578-407d-abf3-af5d07d980f4(suborg TEST)): null)], ch=null, o=SUCCESS, r=null, p=1/1, m=1/1, cuscolprop={}, prop={wf.workItemId=[9fba6bff-6af2-4cd5-b394-6254c1c79d87:4], wf.escalationLevelNumber=[0], wf.stageCount=[1], wf.stageNumber=[1]}, roid=[], ref={wf.object=[AuditObjectReference{oid='98ab9f46-c578-407d-abf3-af5d07d980f4', type={http://midpoint.evolveum.com/xml/ns/public/common/common-3}OrgType, targetName='suborg TEST'}]}], Task(id:1571671311742-0-1, name:null, oid:null))
2019-10-21 17:22:16,942 DEBUG: #### Entry: 2255270           ...task.quartzimpl.TaskManagerQuartzImpl->getNodeId#
2019-10-21 17:22:16,942 TRACE: ###### args: ()
2019-10-21 17:22:16,942 DEBUG: ##### Exit: 2255270            ...task.quartzimpl.TaskManagerQuartzImpl->getNodeId# etime: 0.014 ms
2019-10-21 17:22:16,942 TRACE: ###### retval: DefaultNode
2019-10-21 17:22:16,947 DEBUG: ##### Exit: 2255269           ...init.AuditServiceProxy->audit# etime: 4.725 ms
2019-10-21 17:22:16,947 TRACE: ###### retval: null
2019-10-21 17:22:16,947 DEBUG: #### Entry: 2255271          ...wf.impl.engine.helpers.NotificationHelper->sendPreparedNotifications
2019-10-21 17:22:16,947 TRACE: ###### args: ()
2019-10-21 17:22:16,947 DEBUG: #### Entry: 2255272           ...repo.cache.RepositoryCache->getObject#
2019-10-21 17:22:16,947 TRACE: ###### args: (SystemConfigurationType, 00000000-0000-0000-0000-000000000001, null, R(com.evolveum.midpoint.wf.impl.engine.helpers.NotificationHelper.sendPreparedNotifications UNKNOWN null))
2019-10-21 17:22:16,947 DEBUG: #### Entry: 2255273            ...repo.cache.RepositoryCache->getObject
2019-10-21 17:22:16,947 TRACE: ###### args: (options => null, oid => [00000000-0000-0000-0000-000000000001], type => [http://midpoint.evolveum.com/xml/ns/public/common/common-3#SystemConfigurationType])
2019-10-21 17:22:16,947 DEBUG: #### Entry: 2255274             ...repo.sql.SqlRepositoryServiceImpl->getVersion#
2019-10-21 17:22:16,947 TRACE: ###### args: (SystemConfigurationType, 00000000-0000-0000-0000-000000000001, R(com.evolveum.midpoint.repo.cache.RepositoryCache.getObject UNKNOWN null))
2019-10-21 17:22:16,947 DEBUG: #### Entry: 2255275              ...repo.api.RepositoryService->getVersion
2019-10-21 17:22:16,947 TRACE: ###### args: (oid => [00000000-0000-0000-0000-000000000001], type => [com.evolveum.midpoint.xml.ns._public.common.common_3.SystemConfigurationType])
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255275               ...repo.api.RepositoryService->getVersion etime: 0.833 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255274              ...repo.sql.SqlRepositoryServiceImpl->getVersion# etime: 0.885 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: 187
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255273             ...repo.cache.RepositoryCache->getObject etime: 1.245 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255272            ...repo.cache.RepositoryCache->getObject# etime: 1.311 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: systemConfiguration:00000000-0000-0000-0000-000000000001(SystemConfiguration)
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255271           ...wf.impl.engine.helpers.NotificationHelper->sendPreparedNotifications etime: 1.755 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255257          ...wf.impl.engine.EngineInvocationContext->commit etime: 40.146 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255157         ...wf.impl.engine.WorkflowEngine->executeRequest etime: 25067.345 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255136        ...wf.impl.processors.primary.PrimaryChangeProcessor->executeStartInstructions etime: 25146.234 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,948 DEBUG: ##### Exit: 2255118       ...wf.impl.processors.primary.PrimaryChangeProcessor->previewOrProcessModelInvocation etime: 25153.706 ms
2019-10-21 17:22:16,948 TRACE: ###### retval: {}
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255117      ...wf.impl.hook.WfHook->invoke etime: 25153.876 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: {}
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254939     ...model.impl.lens.Clockwork->click etime: 25198.070 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: {}
2019-10-21 17:22:16,949 DEBUG: #### Entry: 2255276    ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache#
2019-10-21 17:22:16,949 TRACE: ###### args: ()
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2255276     ...provisioning.impl.ProvisioningServiceImpl->exitConstraintsCheckerCache# etime: 0.012 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: null
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254935    ...model.impl.lens.Clockwork->run etime: 25198.487 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: {}
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254934   ...model.api.ModelService->executeChanges etime: 25198.728 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: {}
2019-10-21 17:22:16,949 DEBUG: ##### Exit: 2254933  ...model.impl.controller.ModelController->executeChanges# etime: 25201.841 ms
2019-10-21 17:22:16,949 TRACE: ###### retval: []