diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ChangeExecutor.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ChangeExecutor.java index b242c00360e..e2543a7c8fc 100644 --- a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ChangeExecutor.java +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ChangeExecutor.java @@ -113,6 +113,7 @@ public class ChangeExecutor { @Autowired private ModelObjectResolver objectResolver; @Autowired private OperationalDataManager metadataManager; @Autowired private CredentialsProcessor credentialsProcessor; + @Autowired private ClockworkConflictResolver clockworkConflictResolver; private PrismObjectDefinition userDefinition = null; private PrismObjectDefinition shadowDefinition = null; @@ -182,12 +183,8 @@ public boolean executeChanges(LensContext context, Tas executeDelta(focusDelta, focusContext, context, null, conflictResolution, null, task, subResult); if (focusDelta.isAdd() && focusDelta.getOid() != null) { - // The watcher can already exist; if the OID was pre-existing in the object. - if (context.getFocusConflictWatcher() == null) { - ConflictWatcher watcher = context - .createAndRegisterFocusConflictWatcher(focusDelta.getOid(), cacheRepositoryService); - watcher.setExpectedVersion(focusDelta.getObjectToAdd().getVersion()); - } + clockworkConflictResolver.createConflictWatcherAfterFocusAddition(context, focusDelta.getOid(), + focusDelta.getObjectToAdd().getVersion()); } subResult.computeStatus(); diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java index 2d606df39a9..47b24d73c9d 100644 --- a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/Clockwork.java @@ -7,60 +7,29 @@ package com.evolveum.midpoint.model.impl.lens; import static com.evolveum.midpoint.model.api.ProgressInformation.ActivityType.CLOCKWORK; -import static com.evolveum.midpoint.model.api.ProgressInformation.ActivityType.WAITING; import static com.evolveum.midpoint.model.api.ProgressInformation.StateType.ENTERING; import static com.evolveum.midpoint.model.api.ProgressInformation.StateType.EXITING; import static com.evolveum.midpoint.model.impl.lens.LensUtil.getExportType; import static com.evolveum.midpoint.model.impl.lens.LensUtil.getExportTypeTraceOrReduced; -import static java.util.Collections.emptyList; -import static org.apache.commons.collections4.CollectionUtils.emptyIfNull; -import static org.apache.commons.lang3.ObjectUtils.defaultIfNull; import java.util.ArrayList; import java.util.Collection; -import java.util.Comparator; -import java.util.Date; -import java.util.Iterator; -import java.util.List; - import javax.xml.datatype.XMLGregorianCalendar; -import javax.xml.namespace.QName; -import com.evolveum.midpoint.model.api.ModelAuthorizationAction; -import com.evolveum.midpoint.model.impl.util.AuditHelper; -import com.evolveum.midpoint.prism.*; -import com.evolveum.midpoint.prism.polystring.PolyString; -import com.evolveum.midpoint.schema.cache.CacheConfigurationManager; -import com.evolveum.midpoint.schema.cache.CacheType; -import com.evolveum.midpoint.schema.result.OperationResultBuilder; -import com.evolveum.midpoint.security.enforcer.api.AuthorizationParameters; -import com.evolveum.midpoint.security.enforcer.api.SecurityEnforcer; -import com.evolveum.midpoint.task.api.*; -import com.evolveum.midpoint.util.logging.*; -import com.evolveum.midpoint.xml.ns._public.common.common_3.*; -import org.apache.commons.lang.StringUtils; -import org.apache.commons.lang3.Validate; -import org.jetbrains.annotations.NotNull; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.beans.factory.annotation.Qualifier; import org.springframework.stereotype.Component; -import com.evolveum.midpoint.audit.api.AuditEventRecord; import com.evolveum.midpoint.audit.api.AuditEventStage; -import com.evolveum.midpoint.audit.api.AuditEventType; import com.evolveum.midpoint.common.Clock; +import com.evolveum.midpoint.model.api.ModelAuthorizationAction; import com.evolveum.midpoint.model.api.ModelExecuteOptions; import com.evolveum.midpoint.model.api.ProgressInformation; import com.evolveum.midpoint.model.api.ProgressListener; -import com.evolveum.midpoint.model.api.context.ModelContext; import com.evolveum.midpoint.model.api.context.ModelState; -import com.evolveum.midpoint.model.api.hooks.ChangeHook; import com.evolveum.midpoint.model.api.hooks.HookOperationMode; -import com.evolveum.midpoint.model.api.hooks.HookRegistry; import com.evolveum.midpoint.model.common.SystemObjectCache; import com.evolveum.midpoint.model.common.expression.evaluator.caching.AssociationSearchExpressionEvaluatorCache; -import com.evolveum.midpoint.model.common.expression.script.ScriptExpression; -import com.evolveum.midpoint.model.common.expression.script.ScriptExpressionFactory; import com.evolveum.midpoint.model.impl.lens.projector.ContextLoader; import com.evolveum.midpoint.model.impl.lens.projector.Projector; import com.evolveum.midpoint.model.impl.lens.projector.focus.FocusConstraintsChecker; @@ -69,43 +38,36 @@ import com.evolveum.midpoint.model.impl.migrator.Migrator; import com.evolveum.midpoint.model.impl.sync.RecomputeTaskHandler; import com.evolveum.midpoint.model.impl.util.ModelImplUtils; -import com.evolveum.midpoint.prism.delta.ChangeType; -import com.evolveum.midpoint.prism.delta.ItemDelta; +import com.evolveum.midpoint.prism.*; import com.evolveum.midpoint.prism.delta.ObjectDelta; +import com.evolveum.midpoint.prism.polystring.PolyString; import com.evolveum.midpoint.prism.query.ObjectFilter; -import com.evolveum.midpoint.prism.util.CloneUtil; -import com.evolveum.midpoint.prism.xml.XmlTypeConverter; import com.evolveum.midpoint.provisioning.api.ChangeNotificationDispatcher; import com.evolveum.midpoint.provisioning.api.ProvisioningService; import com.evolveum.midpoint.provisioning.api.ResourceObjectChangeListener; import com.evolveum.midpoint.provisioning.api.ResourceOperationListener; -import com.evolveum.midpoint.repo.api.ConflictWatcher; import com.evolveum.midpoint.repo.api.PreconditionViolationException; import com.evolveum.midpoint.repo.api.RepositoryService; -import com.evolveum.midpoint.repo.common.expression.ExpressionFactory; -import com.evolveum.midpoint.repo.common.expression.ExpressionUtil; -import com.evolveum.midpoint.repo.common.expression.ExpressionVariables; import com.evolveum.midpoint.schema.ObjectDeltaOperation; -import com.evolveum.midpoint.schema.constants.ExpressionConstants; -import com.evolveum.midpoint.schema.constants.ObjectTypes; +import com.evolveum.midpoint.schema.cache.CacheConfigurationManager; +import com.evolveum.midpoint.schema.cache.CacheType; import com.evolveum.midpoint.schema.constants.SchemaConstants; import com.evolveum.midpoint.schema.internals.InternalsConfig; import com.evolveum.midpoint.schema.result.OperationResult; +import com.evolveum.midpoint.schema.result.OperationResultBuilder; import com.evolveum.midpoint.schema.result.OperationResultStatus; -import com.evolveum.midpoint.schema.util.ObjectTypeUtil; import com.evolveum.midpoint.schema.util.SystemConfigurationTypeUtil; +import com.evolveum.midpoint.security.enforcer.api.AuthorizationParameters; +import com.evolveum.midpoint.security.enforcer.api.SecurityEnforcer; +import com.evolveum.midpoint.task.api.*; import com.evolveum.midpoint.util.DebugUtil; import com.evolveum.midpoint.util.Holder; -import com.evolveum.midpoint.util.exception.CommonException; -import com.evolveum.midpoint.util.exception.CommunicationException; -import com.evolveum.midpoint.util.exception.ConfigurationException; -import com.evolveum.midpoint.util.exception.ExpressionEvaluationException; -import com.evolveum.midpoint.util.exception.ObjectAlreadyExistsException; -import com.evolveum.midpoint.util.exception.ObjectNotFoundException; -import com.evolveum.midpoint.util.exception.PolicyViolationException; -import com.evolveum.midpoint.util.exception.SchemaException; -import com.evolveum.midpoint.util.exception.SecurityViolationException; -import com.evolveum.midpoint.util.exception.SystemException; +import com.evolveum.midpoint.util.exception.*; +import com.evolveum.midpoint.util.logging.LevelOverrideTurboFilter; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; +import com.evolveum.midpoint.util.logging.TracingAppender; +import com.evolveum.midpoint.xml.ns._public.common.common_3.*; import com.evolveum.prism.xml.ns._public.query_3.QueryType; import com.evolveum.prism.xml.ns._public.query_3.SearchFilterType; @@ -116,30 +78,20 @@ @Component public class Clockwork { - private static final int DEFAULT_NUMBER_OF_RESULTS_TO_KEEP = 5; - - private static final int DEFAULT_MAX_CONFLICT_RESOLUTION_ATTEMPTS = 1; // synchronize with common-core-3.xsd - private static final int DEFAULT_CONFLICT_RESOLUTION_DELAY_UNIT = 5000; // synchronize with common-core-3.xsd - private static final int MAX_PRECONDITION_CONFLICT_RESOLUTION_ATTEMPTS = 3; - private static final Trace LOGGER = TraceManager.getTrace(Clockwork.class); @Autowired private Projector projector; @Autowired private ContextLoader contextLoader; @Autowired private ChangeExecutor changeExecutor; - @Autowired private AuditHelper auditHelper; @Autowired private Clock clock; @Autowired private SystemObjectCache systemObjectCache; @Autowired private transient ProvisioningService provisioningService; @Autowired private transient ChangeNotificationDispatcher changeNotificationDispatcher; - @Autowired private ExpressionFactory expressionFactory; - @Autowired private ScriptExpressionFactory scriptExpressionFactory; @Autowired private PersonaProcessor personaProcessor; @Autowired private PrismContext prismContext; @Autowired private TaskManager taskManager; @Autowired private Tracer tracer; @Autowired private OperationalDataManager metadataManager; - @Autowired private ContextFactory contextFactory; @Autowired private Migrator migrator; @Autowired private ClockworkMedic medic; @Autowired private PolicyRuleScriptExecutor policyRuleScriptExecutor; @@ -147,9 +99,10 @@ public class Clockwork { @Autowired private ClockworkAuthorizationHelper clockworkAuthorizationHelper; @Autowired private CacheConfigurationManager cacheConfigurationManager; @Autowired private SecurityEnforcer securityEnforcer; - - @Autowired(required = false) - private HookRegistry hookRegistry; + @Autowired private OperationExecutionRecorder operationExecutionRecorder; + @Autowired private ClockworkAuditHelper clockworkAuditHelper; + @Autowired private ClockworkHookHelper clockworkHookHelper; + @Autowired private ClockworkConflictResolver clockworkConflictResolver; @Autowired @Qualifier("cacheRepositoryService") @@ -167,7 +120,7 @@ public HookOperationMode run(LensContext context, Task ClockworkRunTraceType trace = null; try { if (result.isTraced()) { - trace = recordTraceAtStart(context, task, result); + trace = recordTraceAtStart(context, result); } LOGGER.trace("Running clockwork for context {}", context); @@ -176,15 +129,12 @@ public HookOperationMode run(LensContext context, Task } int clicked = 0; - boolean focusConflictPresent = false; - ConflictResolutionType conflictResolutionPolicy = null; + ClockworkConflictResolver.Context conflictResolutionContext = new ClockworkConflictResolver.Context(); HookOperationMode finalMode; try { context.reportProgress(new ProgressInformation(CLOCKWORK, ENTERING)); - if (context.getFocusContext() != null && context.getFocusContext().getOid() != null) { - context.createAndRegisterFocusConflictWatcher(context.getFocusContext().getOid(), repositoryService); - } + clockworkConflictResolver.createConflictWatcherOnStart(context); FocusConstraintsChecker .enterCache(cacheConfigurationManager.getConfiguration(CacheType.LOCAL_FOCUS_CONSTRAINT_CHECKER_CACHE)); enterAssociationSearchExpressionEvaluatorCache(); @@ -193,8 +143,7 @@ public HookOperationMode run(LensContext context, Task while (context.getState() != ModelState.FINAL) { - // TODO implement in model context (as transient or even non-transient attribute) to allow for checking in more complex scenarios - int maxClicks = getMaxClicks(context, result); + int maxClicks = getMaxClicks(result); if (clicked >= maxClicks) { throw new IllegalStateException( "Model operation took too many clicks (limit is " + maxClicks + "). Is there a cycle?"); @@ -213,11 +162,10 @@ public HookOperationMode run(LensContext context, Task // One last click in FINAL state finalMode = click(context, task, result); if (finalMode == HookOperationMode.FOREGROUND) { - conflictResolutionPolicy = ModelImplUtils.getConflictResolution(context); - focusConflictPresent = checkFocusConflicts(context, conflictResolutionPolicy, task, result); + clockworkConflictResolver.checkFocusConflicts(context, conflictResolutionContext, result); } } finally { - context.unregisterConflictWatchers(repositoryService); + clockworkConflictResolver.unregisterConflictWatcher(context); FocusConstraintsChecker.exitCache(); //exitDefaultSearchExpressionEvaluatorCache(); exitAssociationSearchExpressionEvaluatorCache(); @@ -226,12 +174,7 @@ public HookOperationMode run(LensContext context, Task } // intentionally outside the "try-finally" block to start with clean caches - if (focusConflictPresent) { - assert finalMode == HookOperationMode.FOREGROUND; - finalMode = resolveFocusConflict(context, conflictResolutionPolicy, task, result); - } else if (context.getConflictResolutionAttemptNumber() > 0) { - LOGGER.info("Resolved update conflict on attempt number {}", context.getConflictResolutionAttemptNumber()); - } + finalMode = clockworkConflictResolver.resolveFocusConflictIfPresent(context, conflictResolutionContext, finalMode, task, result); result.computeStatusIfUnknown(); return finalMode; } catch (Throwable t) { @@ -241,8 +184,8 @@ public HookOperationMode run(LensContext context, Task recordTraceAtEnd(context, trace, result); if (tracingRequested) { tracer.storeTrace(task, result, parentResult); - TracingAppender.terminateCollecting(); // todo reconsider - LevelOverrideTurboFilter.cancelLoggingOverride(); // todo reconsider + TracingAppender.terminateCollecting(); // reconsider + LevelOverrideTurboFilter.cancelLoggingOverride(); // reconsider } result.computeStatusIfUnknown(); } @@ -270,7 +213,7 @@ private boolean startTracingIfRequested(LensContext co } } - private ClockworkRunTraceType recordTraceAtStart(LensContext context, Task task, + private ClockworkRunTraceType recordTraceAtStart(LensContext context, OperationResult result) throws SchemaException { ClockworkRunTraceType trace = new ClockworkRunTraceType(prismContext); trace.setInputLensContextText(context.debugDump()); @@ -298,18 +241,11 @@ public LensContext previewChanges(LensContext conte try { context.setPreview(true); -// context.setOptions(options); LOGGER.trace("Preview changes context:\n{}", context.debugDumpLazily()); context.setProgressListeners(listeners); projector.projectAllWaves(context, "preview", task, result); - - if (hookRegistry != null) { - for (ChangeHook hook : hookRegistry.getAllChangeHooks()) { - hook.invokePreview(context, task, result); - } - } - + clockworkHookHelper.invokePreview(context, task, result); policyRuleSuspendTaskExecutor.execute(context, task, result); } catch (ConfigurationException | SecurityViolationException | ObjectNotFoundException | SchemaException | @@ -325,12 +261,9 @@ public LensContext previewChanges(LensContext conte // ... and we do not really need that in 3.6.1 // TODO: expose PreconditionViolationException in 3.7 throw new SystemException(e); - } - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("Preview changes output:\n{}", context.debugDump()); - } + LOGGER.debug("Preview changes output:\n{}", context.debugDumpLazily()); result.computeStatus(); result.cleanupResult(); @@ -338,142 +271,6 @@ public LensContext previewChanges(LensContext conte return context; } - private boolean checkFocusConflicts(LensContext context, ConflictResolutionType resolutionPolicy, - Task task, OperationResult result) { - ConflictWatcher watcher = context.getFocusConflictWatcher(); - if (watcher != null && resolutionPolicy != null && resolutionPolicy.getAction() != ConflictResolutionActionType.NONE && - repositoryService.hasConflict(watcher, result)) { - LOGGER.debug("Found modify-modify conflict on {}", watcher); - return true; - } else { - return false; - } - } - - private HookOperationMode resolveFocusConflict(LensContext context, - ConflictResolutionType resolutionPolicy, Task task, OperationResult result) - throws SchemaException, ObjectNotFoundException, ExpressionEvaluationException, ConfigurationException, - CommunicationException, SecurityViolationException, PolicyViolationException, ObjectAlreadyExistsException { - if (resolutionPolicy == null || resolutionPolicy.getAction() == ConflictResolutionActionType.NONE) { - return HookOperationMode.FOREGROUND; - } - PrismObject focusObject = context.getFocusContext() != null ? context.getFocusContext().getObjectAny() : null; - ModelExecuteOptions options = new ModelExecuteOptions(); - switch (resolutionPolicy.getAction()) { - case FAIL: throw new SystemException("Conflict detected while updating " + focusObject); - case LOG: - LOGGER.warn("Conflict detected while updating {}", focusObject); - return HookOperationMode.FOREGROUND; - case RECOMPUTE: - break; - case RECONCILE: - options.setReconcile(); - break; - default: - throw new IllegalStateException("Unsupported conflict resolution action: " + resolutionPolicy.getAction()); - } - - // so, recompute is the action - LOGGER.debug("CONFLICT: Conflict detected while updating {}, recomputing (options={})", focusObject, options); - - if (context.getFocusContext() == null) { - LOGGER.warn("No focus context, not possible to resolve conflict by focus recomputation"); // should really never occur - return HookOperationMode.FOREGROUND; - } - String oid = context.getFocusContext().getOid(); - if (oid == null) { - LOGGER.warn("No focus OID, not possible to resolve conflict by focus recomputation"); // should really never occur - return HookOperationMode.FOREGROUND; - } - Class focusClass = context.getFocusContext().getObjectTypeClass(); - if (focusClass == null) { - LOGGER.warn("Focus class not known, not possible to resolve conflict by focus recomputation"); // should really never occur - return HookOperationMode.FOREGROUND; - } - if (TaskType.class.isAssignableFrom(focusClass)) { - return HookOperationMode.FOREGROUND; // this is actually quite expected, so don't bother anyone with that - } - if (!FocusType.class.isAssignableFrom(focusClass)) { - LOGGER.warn("Focus is not of FocusType (it is {}); not possible to resolve conflict by focus recomputation", focusClass.getName()); - return HookOperationMode.FOREGROUND; - } - - ConflictResolutionType focusConflictResolution = new ConflictResolutionType(); - focusConflictResolution.setAction(ConflictResolutionActionType.ERROR); - options.setFocusConflictResolution(focusConflictResolution); - - int preconditionAttempts = 0; - while (true) { - - int attemptOld = context.getConflictResolutionAttemptNumber(); - int attemptNew = attemptOld + 1; - boolean shouldExecuteAttempt = shouldExecuteAttempt(context, resolutionPolicy, attemptNew); - if (!shouldExecuteAttempt) { - LOGGER.warn("CONFLICT: Couldn't resolve conflict even after {} resolution attempt(s), giving up.", attemptOld); - return HookOperationMode.FOREGROUND; - } - - delay(context, resolutionPolicy, attemptNew + preconditionAttempts); - - PrismObject focus = repositoryService.getObject(focusClass, oid, null, result); - LensContext contextNew = contextFactory.createRecomputeContext(focus, options, task, result); - contextNew.setProgressListeners(new ArrayList<>(emptyIfNull(context.getProgressListeners()))); - contextNew.setConflictResolutionAttemptNumber(attemptNew); - - LOGGER.debug("CONFLICT: Recomputing {} as reaction to conflict (options={}, attempts={},{}, readVersion={})", - context.getFocusContext().getHumanReadableName(), options, attemptNew, preconditionAttempts, contextNew.getFocusContext().getObjectReadVersion()); - - try { - - // this is a recursion; but limited to max attempts which should not be a large number - HookOperationMode hookOperationMode = run(contextNew, task, result); - - // This may be in fact a giveup after recompute that was not able to cleanly proceed. - LOGGER.debug("CONFLICT: Clean recompute (or giveup) of {} achieved (options={}, attempts={},{})", - context.getFocusContext().getHumanReadableName(), options, attemptNew, preconditionAttempts); - - return hookOperationMode; - - } catch (PreconditionViolationException e) { - preconditionAttempts++; - LOGGER.debug("CONFLICT: Recompute precondition failed (attempt {}, precondition attempt {}), trying again", attemptNew, preconditionAttempts); - if (preconditionAttempts < MAX_PRECONDITION_CONFLICT_RESOLUTION_ATTEMPTS) { - continue; - } - LOGGER.warn("CONFLICT: Couldn't resolve conflict even after {} resolution attempt(s) and {} precondition attempts, giving up.", - attemptOld, preconditionAttempts); - return HookOperationMode.FOREGROUND; - } - } - } - - private boolean shouldExecuteAttempt(LensContext context, @NotNull ConflictResolutionType resolutionPolicy, int attemptNew) { - int maxAttempts = defaultIfNull(resolutionPolicy.getMaxAttempts(), DEFAULT_MAX_CONFLICT_RESOLUTION_ATTEMPTS); - if (attemptNew > maxAttempts) { - return false; - } - return true; - } - - private void delay(LensContext context, @NotNull ConflictResolutionType resolutionPolicy, int attempts) { - long delayUnit = defaultIfNull(resolutionPolicy.getDelayUnit(), DEFAULT_CONFLICT_RESOLUTION_DELAY_UNIT); - for (int i = 0; i < attempts; i++) { - delayUnit *= 2; - } - long delay = (long) (Math.random() * delayUnit); - String message = "CONFLICT: Waiting "+delay+" milliseconds before starting conflict resolution (delay exponent: "+attempts+")"; - // TODO convey information about waiting time after some GUI mechanism for displaying it is available - // (showing text messages is currently really ugly) - context.reportProgress(new ProgressInformation(WAITING, EXITING)); - LOGGER.debug(message); - try { - Thread.sleep(delay); - } catch (InterruptedException e) { - // ignore - } - context.reportProgress(new ProgressInformation(WAITING, EXITING)); - } - private void enterAssociationSearchExpressionEvaluatorCache() { AssociationSearchExpressionEvaluatorCache cache = AssociationSearchExpressionEvaluatorCache.enterCache( cacheConfigurationManager.getConfiguration(CacheType.LOCAL_ASSOCIATION_TARGET_SEARCH_EVALUATOR_CACHE)); @@ -503,15 +300,17 @@ private void exitAssociationSearchExpressionEvaluatorCache() { } } + @SuppressWarnings("unused") private void enterDefaultSearchExpressionEvaluatorCache() { //DefaultSearchExpressionEvaluatorCache.enterCache(cacheConfigurationManager.getConfiguration(CacheType.LOCAL_DEFAULT_SEARCH_EVALUATOR_CACHE)); } + @SuppressWarnings("unused") private void exitDefaultSearchExpressionEvaluatorCache() { //DefaultSearchExpressionEvaluatorCache.exitCache(); } - private int getMaxClicks(LensContext context, OperationResult result) throws SchemaException, ObjectNotFoundException { + private int getMaxClicks(OperationResult result) throws SchemaException { PrismObject systemConfiguration = systemObjectCache.getSystemConfiguration(result); Integer maxClicks = SystemConfigurationTypeUtil.getMaxModelClicks(systemConfiguration); if (maxClicks == null) { @@ -566,7 +365,7 @@ public HookOperationMode click(LensContext context, Ta context.generateRequestIdentifierIfNeeded(); // We need to do this BEFORE projection. If we would do that after projection // there will be secondary changes that are not part of the request. - audit(context, AuditEventStage.REQUEST, task, result, parentResult); // we need to take the overall ("run" operation result) not the current one + clockworkAuditHelper.audit(context, AuditEventStage.REQUEST, task, result, parentResult); // we need to take the overall ("run" operation result) not the current one } boolean recompute = false; @@ -608,24 +407,26 @@ public HookOperationMode click(LensContext context, Ta context.checkEncrypted(); } - // LOGGER.info("CLOCKWORK: {}: {}", state, context); - switch (state) { case INITIAL: - processInitialToPrimary(context, task, result); + processInitialToPrimary(context); break; case PRIMARY: processPrimaryToSecondary(context, task, result); break; case SECONDARY: - processSecondary(context, task, result, parentResult); + if (context.getExecutionWave() > context.getMaxWave() + 1) { + processSecondaryToFinal(context, task, result); + } else { + processSecondary(context, task, result, parentResult); + } break; case FINAL: HookOperationMode mode = processFinal(context, task, result, parentResult); medic.clockworkFinish(context); return mode; } - return invokeHooks(context, task, result); + return clockworkHookHelper.invokeHooks(context, task, result); } catch (CommunicationException | ConfigurationException | ExpressionEvaluationException | ObjectNotFoundException | PolicyViolationException | SchemaException | SecurityViolationException | RuntimeException | Error | @@ -644,137 +445,12 @@ public HookOperationMode click(LensContext context, Ta } } - /** - * Invokes hooks, if there are any. - * - * @return - * - ERROR, if any hook reported error; otherwise returns - * - BACKGROUND, if any hook reported switching to background; otherwise - * - FOREGROUND (if all hooks reported finishing on foreground) - */ - private HookOperationMode invokeHooks(LensContext context, Task task, OperationResult result) throws ExpressionEvaluationException, ObjectNotFoundException, SchemaException, PolicyViolationException, CommunicationException, ConfigurationException, SecurityViolationException { - // TODO: following two parts should be merged together in later versions - - // Execute configured scripting hooks - PrismObject systemConfiguration = systemObjectCache.getSystemConfiguration(result); - // systemConfiguration may be null in some tests - if (systemConfiguration != null) { - ModelHooksType modelHooks = systemConfiguration.asObjectable().getModelHooks(); - if (modelHooks != null) { - HookListType changeHooks = modelHooks.getChange(); - if (changeHooks != null) { - for (HookType hookType: changeHooks.getHook()) { - String shortDesc; - if (hookType.getName() != null) { - shortDesc = "hook '"+hookType.getName()+"'"; - } else { - shortDesc = "scripting hook in system configuration"; - } - if (hookType.isEnabled() != null && !hookType.isEnabled()) { - // Disabled hook, skip - continue; - } - if (hookType.getState() != null) { - if (!context.getState().toModelStateType().equals(hookType.getState())) { - continue; - } - } - if (hookType.getFocusType() != null) { - if (context.getFocusContext() == null) { - continue; - } - QName hookFocusTypeQname = hookType.getFocusType(); - ObjectTypes hookFocusType = ObjectTypes.getObjectTypeFromTypeQName(hookFocusTypeQname); - if (hookFocusType == null) { - throw new SchemaException("Unknown focus type QName "+hookFocusTypeQname+" in "+shortDesc); - } - Class focusClass = context.getFocusClass(); - Class hookFocusClass = hookFocusType.getClassDefinition(); - if (!hookFocusClass.isAssignableFrom(focusClass)) { - continue; - } - } - - ScriptExpressionEvaluatorType scriptExpressionEvaluatorType = hookType.getScript(); - if (scriptExpressionEvaluatorType == null) { - continue; - } - try { - evaluateScriptingHook(context, hookType, scriptExpressionEvaluatorType, shortDesc, task, result); - } catch (ExpressionEvaluationException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new ExpressionEvaluationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } catch (ObjectNotFoundException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new ObjectNotFoundException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } catch (SchemaException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new SchemaException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } catch (CommunicationException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new CommunicationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } catch (ConfigurationException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new ConfigurationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } catch (SecurityViolationException e) { - LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); - throw new SecurityViolationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); - } - } - } - } - } - - // Execute registered Java hooks - HookOperationMode resultMode = HookOperationMode.FOREGROUND; - if (hookRegistry != null) { - for (ChangeHook hook : hookRegistry.getAllChangeHooks()) { - HookOperationMode mode = hook.invoke(context, task, result); - if (mode == HookOperationMode.ERROR) { - resultMode = HookOperationMode.ERROR; - } else if (mode == HookOperationMode.BACKGROUND) { - if (resultMode != HookOperationMode.ERROR) { - resultMode = HookOperationMode.BACKGROUND; - } - } - } - } - return resultMode; - } - - - private void evaluateScriptingHook(LensContext context, HookType hookType, - ScriptExpressionEvaluatorType scriptExpressionEvaluatorType, String shortDesc, Task task, OperationResult result) - throws ExpressionEvaluationException, ObjectNotFoundException, SchemaException, CommunicationException, ConfigurationException, SecurityViolationException { - - LOGGER.trace("Evaluating {}", shortDesc); - // TODO: it would be nice to cache this - // null output definition: this script has no output - ScriptExpression scriptExpression = scriptExpressionFactory.createScriptExpression(scriptExpressionEvaluatorType, null, context.getPrivilegedExpressionProfile(), expressionFactory, shortDesc, task, result); - - ExpressionVariables variables = new ExpressionVariables(); - variables.put(ExpressionConstants.VAR_PRISM_CONTEXT, prismContext, PrismContext.class); - variables.put(ExpressionConstants.VAR_MODEL_CONTEXT, context, ModelContext.class); - LensFocusContext focusContext = context.getFocusContext(); - PrismObject focus = null; - if (focusContext != null) { - variables.put(ExpressionConstants.VAR_FOCUS, focusContext.getObjectAny(), focusContext.getObjectDefinition()); - } else { - PrismObjectDefinition def = prismContext.getSchemaRegistry().findObjectDefinitionByCompileTimeClass(ObjectType.class); - variables.put(ExpressionConstants.VAR_FOCUS, null, def); - } - - - ModelImplUtils.evaluateScript(scriptExpression, context, variables, false, shortDesc, task, result); - LOGGER.trace("Finished evaluation of {}", shortDesc); - } - private void switchState(LensContext context, ModelState newState) { medic.clockworkStateSwitch(context, newState); context.setState(newState); } - private void processInitialToPrimary(LensContext context, Task task, OperationResult result) { + private void processInitialToPrimary(LensContext context) { // Context loaded, nothing special do. Bump state to PRIMARY. switchState(context, ModelState.PRIMARY); } @@ -784,18 +460,13 @@ private void processPrimaryToSecondary(LensContext con switchState(context, ModelState.SECONDARY); policyRuleSuspendTaskExecutor.execute(context, task, result); - } private void processSecondary(LensContext context, Task task, OperationResult result, OperationResult overallResult) throws ObjectAlreadyExistsException, ObjectNotFoundException, SchemaException, CommunicationException, ConfigurationException, SecurityViolationException, ExpressionEvaluationException, PolicyViolationException, PreconditionViolationException { - if (context.getExecutionWave() > context.getMaxWave() + 1) { - processSecondaryToFinal(context, task, result); - return; - } - Holder restartRequestedHolder = new Holder<>(); + Holder restartRequestedHolder = new Holder<>(false); medic.partialExecute("execution", (result1) -> { @@ -805,113 +476,31 @@ private void processSecondary(LensContext context, Tas context.getPartialProcessingOptions()::getExecution, Clockwork.class, context, result); - audit(context, AuditEventStage.EXECUTION, task, result, overallResult); + clockworkAuditHelper.audit(context, AuditEventStage.EXECUTION, task, result, overallResult); - rotContextIfNeeded(context); - - boolean restartRequested = false; - if (restartRequestedHolder.getValue() != null) { - restartRequested = restartRequestedHolder.getValue(); - } + context.rotIfNeeded(); - if (!restartRequested) { - // TODO what if restart is requested indefinitely? + if (!restartRequestedHolder.getValue()) { context.incrementExecutionWave(); } else { - // explicitly rot context? + // Shouldn't we explicitly rot context here? + // BTW, what if restart is requested indefinitely? } medic.traceContext(LOGGER, "CLOCKWORK (" + context.getState() + ")", "change execution", false, context, false); } - - private void processSecondaryToFinal(LensContext context, Task task, OperationResult result) throws PolicyViolationException { + private void processSecondaryToFinal(LensContext context, Task task, OperationResult result) { switchState(context, ModelState.FINAL); policyRuleScriptExecutor.execute(context, task, result); } - /** - * Force recompute for the next execution wave. Recompute only those contexts that were changed. - * This is more intelligent than context.rot() - */ - private void rotContextIfNeeded(LensContext context) throws SchemaException { - boolean rot = false; - for (LensProjectionContext projectionContext: context.getProjectionContexts()) { - if (projectionContext.getWave() != context.getExecutionWave()) { - LOGGER.trace("Context rot: projection {} NOT rotten because of wrong wave number", projectionContext); - continue; - } -// if (!projectionContext.isDoReconciliation()) { // meaning volatility is NONE -// LOGGER.trace("Context rot: projection {} NOT rotten because the resource is non-volatile", projectionContext); -// continue; -// } - ObjectDelta execDelta = projectionContext.getExecutableDelta(); - if (isShadowDeltaSignificant(execDelta)) { - - LOGGER.debug("Context rot: projection {} rotten because of executable delta {}", projectionContext, execDelta); - projectionContext.setFresh(false); - projectionContext.setFullShadow(false); - rot = true; - // Propagate to higher-order projections - for (LensProjectionContext relCtx: LensUtil.findRelatedContexts(context, projectionContext)) { - relCtx.setFresh(false); - relCtx.setFullShadow(false); - } - - } else { - LOGGER.trace("Context rot: projection {} NOT rotten because no delta", projectionContext); - } - } - LensFocusContext focusContext = context.getFocusContext(); - if (focusContext != null) { - ObjectDelta execDelta = focusContext.getWaveDelta(context.getExecutionWave()); - if (execDelta != null && !execDelta.isEmpty()) { - LOGGER.debug("Context rot: context rotten because of focus execution delta {}", execDelta); - rot = true; - } - if (rot) { - // It is OK to refresh focus all the time there was any change. This is cheap. - focusContext.setFresh(false); - } - //remove secondary deltas from other than execution wave - we need to recompute them.. -// cleanUpSecondaryDeltas(context); - - - } - if (rot) { - context.setFresh(false); - } - } - -// // TODO this is quite unclear. Originally here was keeping the delta from the current wave (plus delta from wave #1). -// // The reason was not clear. -// // Let us erase everything. -// private void cleanUpSecondaryDeltas(LensContext context){ -// LensFocusContext focusContext = context.getFocusContext(); -// ObjectDeltaWaves executionWaveDeltaList = focusContext.getSecondaryDeltas(); -// executionWaveDeltaList.clear(); -// } - - private

boolean isShadowDeltaSignificant(ObjectDelta

delta) { - if (delta == null || delta.isEmpty()) { - return false; - } - if (delta.isAdd() || delta.isDelete()) { - return true; - } - Collection> attrDeltas = delta.findItemDeltasSubPath(ShadowType.F_ATTRIBUTES); - if (attrDeltas != null && !attrDeltas.isEmpty()) { - return true; - } - return false; - } - private HookOperationMode processFinal(LensContext context, Task task, OperationResult result, OperationResult overallResult) throws ObjectAlreadyExistsException, ObjectNotFoundException, SchemaException, CommunicationException, ConfigurationException, SecurityViolationException, ExpressionEvaluationException, PolicyViolationException, PreconditionViolationException { - auditFinalExecution(context, task, result, overallResult); - logFinalReadable(context, task, result); - recordOperationExecution(context, null, task, result); + clockworkAuditHelper.auditFinalExecution(context, task, result, overallResult); + logFinalReadable(context); + operationExecutionRecorder.recordOperationExecution(context, null, task, result); migrator.executeAfterOperationMigration(context, result); HookOperationMode opmode = personaProcessor.processPersonaChanges(context, task, result); @@ -922,274 +511,7 @@ private HookOperationMode processFinal(LensContext con return triggerReconcileAffected(context, task, result); } - private void recordOperationExecution(LensContext context, Throwable clockworkException, - Task task, OperationResult result) { - boolean skip = context.getInternalsConfiguration() != null && - context.getInternalsConfiguration().getOperationExecutionRecording() != null && - Boolean.TRUE.equals(context.getInternalsConfiguration().getOperationExecutionRecording().isSkip()); - if (!skip) { - XMLGregorianCalendar now = clock.currentTimeXMLGregorianCalendar(); - try { - LOGGER.trace("recordOperationExecution starting; task = {}, clockworkException = {}", task, clockworkException); - boolean opRecordedIntoFocus = recordFocusOperationExecution(context, now, clockworkException, task, result); - for (LensProjectionContext projectionContext : context.getProjectionContexts()) { - Throwable exceptionToProjection; - if (clockworkException != null && !opRecordedIntoFocus && projectionContext.isSynchronizationSource()) { - // We need to record the exception somewhere. Because we were not able to put it into focus, - // we have to do it into sync-source projection. - exceptionToProjection = clockworkException; - } else { - exceptionToProjection = null; - } - recordProjectionOperationExecution(context, projectionContext, now, exceptionToProjection, task, result); - } - } catch (Throwable t) { - LoggingUtils.logUnexpectedException(LOGGER, "Couldn't record operation execution. Model context:\n{}", t, - context.debugDump()); - // Let us ignore this for the moment. It should not have happened, sure. But it's not that crucial. - // Administrator will be able to learn about the problem from the log. - } - } else { - LOGGER.trace("Skipping operation execution recording (as set in system configuration)"); - } - } - - /** - * @return true if the operation execution was recorded (or would be recorded, but skipped because of the configuration) - */ - private boolean recordFocusOperationExecution(LensContext context, XMLGregorianCalendar now, - Throwable clockworkException, Task task, OperationResult result) - throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { - LensFocusContext focusContext = context.getFocusContext(); - if (focusContext == null || focusContext.isDelete()) { - LOGGER.trace("focusContext is null or 'delete', not recording focus operation execution"); - return false; - } - PrismObject objectNew = focusContext.getObjectNew(); - Validate.notNull(objectNew, "No focus object even if the context is not of 'delete' type"); - - //noinspection unchecked - List> executedDeltas = getExecutedDeltas(focusContext, - (Class) objectNew.asObjectable().getClass(), clockworkException, result); - LOGGER.trace("recordFocusOperationExecution: executedDeltas: {}", executedDeltas.size()); - return recordOperationExecution(objectNew, false, executedDeltas, now, context.getChannel(), - getSkipWhenSuccess(context), task, result); - } - - @NotNull - private List> getExecutedDeltas(LensElementContext elementContext, - Class objectClass, Throwable clockworkException, OperationResult result) { - List> executedDeltas; - if (clockworkException != null) { - executedDeltas = new ArrayList<>(elementContext.getExecutedDeltas()); - LensObjectDeltaOperation odo = new LensObjectDeltaOperation<>(); - ObjectDelta primaryDelta = elementContext.getPrimaryDelta(); - if (primaryDelta != null) { - odo.setObjectDelta(primaryDelta); - } else { - ObjectDelta fakeDelta = prismContext.deltaFactory().object().create(objectClass, ChangeType.MODIFY); - odo.setObjectDelta(fakeDelta); - } - odo.setExecutionResult(result); // we rely on the fact that 'result' already contains record of the exception - executedDeltas.add(odo); - } else { - executedDeltas = elementContext.getExecutedDeltas(); - } - return executedDeltas; - } - - private boolean getSkipWhenSuccess(LensContext context) { - return context.getInternalsConfiguration() != null && - context.getInternalsConfiguration().getOperationExecutionRecording() != null && - Boolean.TRUE.equals(context.getInternalsConfiguration().getOperationExecutionRecording().isSkipWhenSuccess()); - } - - private void recordProjectionOperationExecution(LensContext context, - LensProjectionContext projectionContext, XMLGregorianCalendar now, Throwable clockworkException, - Task task, OperationResult result) throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { - PrismObject object = projectionContext.getObjectAny(); - if (object == null) { - return; // this can happen - } - List> executedDeltas = getExecutedDeltas(projectionContext, ShadowType.class, - clockworkException, result); - recordOperationExecution(object, true, executedDeltas, now, - context.getChannel(), getSkipWhenSuccess(context), task, result); - } - - /** - * @return true if the operation execution was recorded (or would be recorded, but skipped because of the configuration) - */ - private boolean recordOperationExecution(PrismObject object, boolean deletedOk, - List> executedDeltas, XMLGregorianCalendar now, - String channel, boolean skipWhenSuccess, Task task, OperationResult result) - throws ObjectAlreadyExistsException, ObjectNotFoundException, SchemaException { - OperationExecutionType operation = new OperationExecutionType(prismContext); - OperationResult summaryResult = new OperationResult("recordOperationExecution"); - String oid = object.getOid(); - for (LensObjectDeltaOperation deltaOperation : executedDeltas) { - operation.getOperation().add(createObjectDeltaOperation(deltaOperation)); - if (deltaOperation.getExecutionResult() != null) { - summaryResult.addSubresult(deltaOperation.getExecutionResult().clone()); // todo eliminate this clone (but beware of modifying the subresult) - } - if (oid == null && deltaOperation.getObjectDelta() != null) { - oid = deltaOperation.getObjectDelta().getOid(); - } - } - if (oid == null) { // e.g. if there is an exception in provisioning.addObject method - LOGGER.trace("recordOperationExecution: skipping because oid is null for object = {}", object); - return false; - } - summaryResult.computeStatus(); - OperationResultStatusType overallStatus = summaryResult.getStatus().createStatusType(); - setOperationContext(operation, overallStatus, now, channel, task); - storeOperationExecution(object, oid, operation, deletedOk, skipWhenSuccess, result); - return true; - } - - private void storeOperationExecution(@NotNull PrismObject object, @NotNull String oid, - @NotNull OperationExecutionType executionToAdd, boolean deletedOk, boolean skipWhenSuccess, OperationResult result) - throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { - Integer recordsToKeep; - Long deleteBefore; - boolean keepNoExecutions = false; - PrismObject systemConfiguration = systemObjectCache.getSystemConfiguration(result); - if (systemConfiguration != null && systemConfiguration.asObjectable().getCleanupPolicy() != null - && systemConfiguration.asObjectable().getCleanupPolicy().getObjectResults() != null) { - CleanupPolicyType policy = systemConfiguration.asObjectable().getCleanupPolicy().getObjectResults(); - recordsToKeep = policy.getMaxRecords(); - if (recordsToKeep != null && recordsToKeep == 0) { - LOGGER.trace("objectResults.recordsToKeep is 0, will skip storing operationExecutions"); - keepNoExecutions = true; - } - if (policy.getMaxAge() != null) { - XMLGregorianCalendar limit = XmlTypeConverter.addDuration( - XmlTypeConverter.createXMLGregorianCalendar(new Date()), policy.getMaxAge().negate()); - deleteBefore = XmlTypeConverter.toMillis(limit); - } else { - deleteBefore = null; - } - } else { - recordsToKeep = DEFAULT_NUMBER_OF_RESULTS_TO_KEEP; - deleteBefore = null; - } - - String taskOid = executionToAdd.getTaskRef() != null ? executionToAdd.getTaskRef().getOid() : null; - if (executionToAdd.getStatus() == OperationResultStatusType.SUCCESS && skipWhenSuccess) { - // We want to skip writing operationExecution. But let's check if there are some older non-success results - // related to the current task - if (taskOid != null) { - boolean hasNonSuccessFromCurrentTask = object.asObjectable().getOperationExecution().stream() - .anyMatch(oe -> oe.getTaskRef() != null && taskOid.equals(oe.getTaskRef().getOid()) && - oe.getStatus() != OperationResultStatusType.SUCCESS); - if (hasNonSuccessFromCurrentTask) { - LOGGER.trace("Cannot skip OperationExecution recording because there's an older non-success record from the current task"); - } else { - LOGGER.trace("Skipping OperationExecution recording because status is SUCCESS and skipWhenSuccess is true " - + "(and no older non-success records for current task {} exist)", taskOid); - return; - } - } else { - LOGGER.trace("Skipping OperationExecution recording because status is SUCCESS and skipWhenSuccess is true"); - return; - } - } - List executionsToDelete = new ArrayList<>(); - List executions = new ArrayList<>(object.asObjectable().getOperationExecution()); - // delete all executions related to current task and all old ones - for (Iterator iterator = executions.iterator(); iterator.hasNext(); ) { - OperationExecutionType execution = iterator.next(); - boolean isPreviousTaskResult = taskOid != null && execution.getTaskRef() != null && taskOid.equals(execution.getTaskRef().getOid()); - boolean isOld = deleteBefore != null && XmlTypeConverter.toMillis(execution.getTimestamp()) < deleteBefore; - if (isPreviousTaskResult || isOld) { - executionsToDelete.add(execution); - iterator.remove(); - } - } - - // delete all surplus executions - if (recordsToKeep != null && executions.size() > recordsToKeep - 1) { - if (keepNoExecutions) { - executionsToDelete.addAll(executions); - } else { - executions.sort(Comparator.nullsFirst(Comparator.comparing(e -> XmlTypeConverter.toDate(e.getTimestamp())))); - executionsToDelete.addAll(executions.subList(0, executions.size() - (recordsToKeep - 1))); - } - } - // construct and execute the delta - Class objectClass = object.asObjectable().getClass(); - List> deltas = new ArrayList<>(); - if (!keepNoExecutions) { - deltas.add(prismContext.deltaFor(objectClass) - .item(ObjectType.F_OPERATION_EXECUTION) - .add(executionToAdd) - .asItemDelta()); - } - if (!executionsToDelete.isEmpty()) { - deltas.add(prismContext.deltaFor(objectClass) - .item(ObjectType.F_OPERATION_EXECUTION) - .delete(PrismContainerValue.toPcvList(CloneUtil.cloneCollectionMembers(executionsToDelete))) - .asItemDelta()); - } - LOGGER.trace("Operation execution delta:\n{}", DebugUtil.debugDumpLazily(deltas)); - try { - if (!deltas.isEmpty()) { - repositoryService.modifyObject(objectClass, oid, deltas, result); - } - } catch (ObjectNotFoundException e) { - if (!deletedOk) { - throw e; - } else { - LOGGER.trace("Object {} deleted but this was expected.", oid); - result.deleteLastSubresultIfError(); - } - } - } - - private void setOperationContext(OperationExecutionType operation, - OperationResultStatusType overallStatus, XMLGregorianCalendar now, String channel, Task task) { - if (task instanceof RunningTask && ((RunningTask) task).getParentForLightweightAsynchronousTask() != null) { - task = ((RunningTask) task).getParentForLightweightAsynchronousTask(); - } - if (task.isPersistent()) { - operation.setTaskRef(task.getSelfReference()); - } - operation.setStatus(overallStatus); - operation.setInitiatorRef(ObjectTypeUtil.createObjectRef(task.getOwner(), prismContext)); // TODO what if the real initiator is different? (e.g. when executing approved changes) - operation.setChannel(channel); - operation.setTimestamp(now); - } - - private ObjectDeltaOperationType createObjectDeltaOperation(LensObjectDeltaOperation deltaOperation) { - ObjectDeltaOperationType odo; - try { - odo = simplifyOperation(deltaOperation).toLensObjectDeltaOperationType().getObjectDeltaOperation(); - } catch (SchemaException e) { - LoggingUtils.logUnexpectedException(LOGGER, "Couldn't create operation information", e); - odo = new ObjectDeltaOperationType(); - OperationResult r = new OperationResult(Clockwork.class.getName() + ".createObjectDeltaOperation"); - r.recordFatalError("Couldn't create operation information: " + e.getMessage(), e); - odo.setExecutionResult(r.createOperationResultType()); - } - return odo; - } - - private LensObjectDeltaOperation simplifyOperation(ObjectDeltaOperation operation) { - LensObjectDeltaOperation rv = new LensObjectDeltaOperation<>(); - rv.setObjectDelta(simplifyDelta(operation.getObjectDelta())); - rv.setExecutionResult(OperationResult.keepRootOnly(operation.getExecutionResult())); - rv.setObjectName(operation.getObjectName()); - rv.setResourceName(operation.getResourceName()); - rv.setResourceOid(operation.getResourceOid()); - return rv; - } - - private ObjectDelta simplifyDelta(ObjectDelta delta) { - return prismContext.deltaFactory().object().create(delta.getObjectTypeClass(), delta.getChangeType()); - } - private HookOperationMode triggerReconcileAffected(LensContext context, Task task, OperationResult result) throws SchemaException { - // check applicability if (!ModelExecuteOptions.isReconcileAffected(context.getOptions())) { return HookOperationMode.FOREGROUND; } @@ -1202,9 +524,9 @@ private HookOperationMode triggerReconcileAffected(LensCo if (context.getFocusContext() == null) { throw new IllegalStateException("No focus context when expected it"); } - PrismObject role = (PrismObject) context.getFocusContext().getObjectAny(); + PrismObject role = context.getFocusContext().getObjectAny(); if (role == null) { - throw new IllegalStateException("No role when expected it"); + throw new IllegalStateException("No focus object when expected it"); } // preparing the recompute/reconciliation task @@ -1226,6 +548,7 @@ private HookOperationMode triggerReconcileAffected(LensCo SearchFilterType filterType = prismContext.getQueryConverter().createSearchFilterType(refFilter); QueryType queryType = new QueryType(); queryType.setFilter(filterType); + //noinspection unchecked PrismProperty property = propertyDef.instantiate(); property.setRealValue(queryType); reconTask.addExtensionProperty(property); @@ -1242,263 +565,20 @@ private HookOperationMode triggerReconcileAffected(LensCo return HookOperationMode.BACKGROUND; } - // "overallResult" covers the whole clockwork run - // while "result" is - most of the time - related to the current clockwork click - private void audit(LensContext context, AuditEventStage stage, Task task, OperationResult result, OperationResult overallResult) throws SchemaException { - if (context.isLazyAuditRequest()) { - if (stage == AuditEventStage.REQUEST) { - // We skip auditing here, we will do it before execution - } else if (stage == AuditEventStage.EXECUTION) { - Collection> unauditedExecutedDeltas = context.getUnauditedExecutedDeltas(); - if ((unauditedExecutedDeltas == null || unauditedExecutedDeltas.isEmpty())) { - // No deltas, nothing to audit in this wave - return; - } - if (!context.isRequestAudited()) { - auditEvent(context, AuditEventStage.REQUEST, context.getStats().getRequestTimestamp(), false, task, result, overallResult); - } - auditEvent(context, stage, null, false, task, result, overallResult); - } - } else { - auditEvent(context, stage, null, false, task, result, overallResult); - } - } - - /** - * Make sure that at least one execution is audited if a request was already audited. We don't want - * request without execution in the audit logs. - */ - private void auditFinalExecution(LensContext context, Task task, OperationResult result, - OperationResult overallResult) throws SchemaException { - if (!context.isRequestAudited()) { - return; - } - if (context.isExecutionAudited()) { - return; - } - auditEvent(context, AuditEventStage.EXECUTION, null, true, task, result, overallResult); - } - private void processClockworkException(LensContext context, Throwable e, Task task, OperationResult result, OperationResult overallResult) - throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { + throws SchemaException { LOGGER.trace("Processing clockwork exception {}", e.toString()); result.recordFatalErrorNotFinish(e); - auditEvent(context, AuditEventStage.EXECUTION, null, true, task, result, overallResult); - recordOperationExecution(context, e, task, result); + clockworkAuditHelper.auditEvent(context, AuditEventStage.EXECUTION, null, true, task, result, overallResult); + operationExecutionRecorder.recordOperationExecution(context, e, task, result); LensUtil.reclaimSequences(context, repositoryService, task, result); result.recordEnd(); } - // "overallResult" covers the whole clockwork run - // while "result" is - most of the time - related to the current clockwork click - // - // We provide "result" here just for completeness - if any of the called methods would like to record to it. - private void auditEvent(LensContext context, AuditEventStage stage, - XMLGregorianCalendar timestamp, boolean alwaysAudit, Task task, OperationResult result, - OperationResult overallResult) throws SchemaException { - - PrismObject primaryObject; - ObjectDelta primaryDelta; - if (context.getFocusContext() != null) { - primaryObject = context.getFocusContext().getObjectOld(); - if (primaryObject == null) { - primaryObject = context.getFocusContext().getObjectNew(); - } - primaryDelta = context.getFocusContext().getDelta(); - } else { - Collection projectionContexts = context.getProjectionContexts(); - if (projectionContexts == null || projectionContexts.isEmpty()) { - throw new IllegalStateException("No focus and no projections in "+context); - } - if (projectionContexts.size() > 1) { - throw new IllegalStateException("No focus and more than one projection in "+context); - } - LensProjectionContext projection = projectionContexts.iterator().next(); - primaryObject = projection.getObjectOld(); - if (primaryObject == null) { - primaryObject = projection.getObjectNew(); - } - primaryDelta = projection.getDelta(); - } - - AuditEventType eventType; - if (primaryDelta == null) { - eventType = AuditEventType.SYNCHRONIZATION; - } else if (primaryDelta.isAdd()) { - eventType = AuditEventType.ADD_OBJECT; - } else if (primaryDelta.isModify()) { - eventType = AuditEventType.MODIFY_OBJECT; - } else if (primaryDelta.isDelete()) { - eventType = AuditEventType.DELETE_OBJECT; - } else { - throw new IllegalStateException("Unknown state of delta "+primaryDelta); - } - - AuditEventRecord auditRecord = new AuditEventRecord(eventType, stage); - auditRecord.setRequestIdentifier(context.getRequestIdentifier()); - - boolean recordResourceOids; - List propertiesToRecord; - SystemConfigurationType config = context.getSystemConfigurationType(); - if (config != null && config.getAudit() != null && config.getAudit().getEventRecording() != null) { - SystemConfigurationAuditEventRecordingType eventRecording = config.getAudit().getEventRecording(); - recordResourceOids = Boolean.TRUE.equals(eventRecording.isRecordResourceOids()); - propertiesToRecord = eventRecording.getProperty(); - } else { - recordResourceOids = false; - propertiesToRecord = emptyList(); - } - - if (primaryObject != null) { - auditRecord.setTarget(primaryObject, prismContext); - if (recordResourceOids) { - if (primaryObject.getRealValue() instanceof FocusType) { - FocusType focus = (FocusType) primaryObject.getRealValue(); - for (ObjectReferenceType shadowRef : focus.getLinkRef()) { - LensProjectionContext projectionContext = context.findProjectionContextByOid(shadowRef.getOid()); - if (projectionContext != null && StringUtils.isNotBlank(projectionContext.getResourceOid())) { - auditRecord.addResourceOid(projectionContext.getResourceOid()); - } - } - } else if (primaryObject.getRealValue() instanceof ShadowType) { - ObjectReferenceType resource = ((ShadowType) primaryObject.getRealValue()).getResourceRef(); - if (resource != null && resource.getOid() != null) { - auditRecord.addResourceOid(resource.getOid()); - } - } - } - } - - auditRecord.setChannel(context.getChannel()); - - // This is a brutal hack -- FIXME: create some "compute in-depth preview" method on operation result - OperationResult clone = overallResult.clone(2, false); - for (OperationResult subresult : clone.getSubresults()) { - subresult.computeStatusIfUnknown(); - } - clone.computeStatus(); - - if (stage == AuditEventStage.REQUEST) { - Collection> clonedDeltas = ObjectDeltaOperation.cloneDeltaCollection(context.getPrimaryChanges()); - checkNamesArePresent(clonedDeltas, primaryObject); - auditRecord.addDeltas(clonedDeltas); - if (auditRecord.getTarget() == null) { - auditRecord.setTarget(ModelImplUtils.determineAuditTargetDeltaOps(clonedDeltas, context.getPrismContext())); - } - } else if (stage == AuditEventStage.EXECUTION) { - auditRecord.setOutcome(clone.getStatus()); - Collection> unauditedExecutedDeltas = context.getUnauditedExecutedDeltas(); - if (!alwaysAudit && (unauditedExecutedDeltas == null || unauditedExecutedDeltas.isEmpty())) { - // No deltas, nothing to audit in this wave - return; - } - Collection> clonedDeltas = ObjectDeltaOperation.cloneCollection(unauditedExecutedDeltas); - checkNamesArePresent(clonedDeltas, primaryObject); - auditRecord.addDeltas(clonedDeltas); - } else { - throw new IllegalStateException("Unknown audit stage "+stage); - } - - if (timestamp != null) { - auditRecord.setTimestamp(XmlTypeConverter.toMillis(timestamp)); - } - - addRecordMessage(auditRecord, clone.getMessage()); - - for (SystemConfigurationAuditEventRecordingPropertyType property : propertiesToRecord) { - String name = property.getName(); - if (StringUtils.isBlank(name)) { - throw new IllegalArgumentException("Name of SystemConfigurationAuditEventRecordingPropertyType is empty or null in " + property); - } - ExpressionType expression = property.getExpression(); - if (expression != null) { - ExpressionVariables variables = new ExpressionVariables(); - variables.put(ExpressionConstants.VAR_TARGET, primaryObject, PrismObject.class); - variables.put(ExpressionConstants.VAR_AUDIT_RECORD, auditRecord, AuditEventRecord.class); - String shortDesc = "value for custom column of audit table"; - try { - Collection values = ExpressionUtil.evaluateStringExpression(variables, prismContext, expression, context.getPrivilegedExpressionProfile(), expressionFactory, shortDesc, task, result); - if (values != null && !values.isEmpty()) { - if (values.size() > 1) { - throw new IllegalArgumentException("Collection of expression result contains more as one value"); - } - auditRecord.getCustomColumnProperty().put(name, values.iterator().next()); - } - } catch (CommonException e) { - LOGGER.error("Couldn't evaluate Expression " + expression.toString(), e); - } - } - } - - auditHelper.audit(auditRecord, context.getNameResolver(), task, result); - - if (stage == AuditEventStage.EXECUTION) { - // We need to clean up so these deltas will not be audited again in next wave - context.markExecutedDeltasAudited(); - context.setExecutionAudited(true); - } else { - assert stage == AuditEventStage.REQUEST; - context.setRequestAudited(true); - } - } - - private void checkNamesArePresent(Collection> deltas, PrismObject primaryObject) { - if (primaryObject != null) { - for (ObjectDeltaOperation delta : deltas) { - if (delta.getObjectName() == null) { - delta.setObjectName(primaryObject.getName()); - } - } - } - } - - /** - * Adds a message to the record by pulling the messages from individual delta results. - */ - private void addRecordMessage(AuditEventRecord auditRecord, String message) { - if (auditRecord.getMessage() != null) { - return; - } - if (!StringUtils.isEmpty(message)) { - auditRecord.setMessage(message); - return; - } - Collection> deltas = auditRecord.getDeltas(); - if (deltas == null || deltas.isEmpty()) { - return; - } - StringBuilder sb = new StringBuilder(); - for (ObjectDeltaOperation delta: deltas) { - OperationResult executionResult = delta.getExecutionResult(); - if (executionResult != null) { - String deltaMessage = executionResult.getMessage(); - if (!StringUtils.isEmpty(deltaMessage)) { - if (sb.length() != 0) { - sb.append("; "); - } - sb.append(deltaMessage); - } - } - } - auditRecord.setMessage(sb.toString()); - } - - public static void throwException(Throwable e) throws ObjectAlreadyExistsException, ObjectNotFoundException { - if (e instanceof ObjectAlreadyExistsException) { - throw (ObjectAlreadyExistsException)e; - } else if (e instanceof ObjectNotFoundException) { - throw (ObjectNotFoundException)e; - } else if (e instanceof SystemException) { - throw (SystemException)e; - } else { - throw new SystemException("Unexpected exception "+e.getClass()+" "+e.getMessage(), e); - } - } - /** * Logs the entire operation in a human-readable fashion. */ - private void logFinalReadable(LensContext context, Task task, OperationResult result) throws SchemaException { + private void logFinalReadable(LensContext context) { if (!LOGGER.isDebugEnabled()) { return; } @@ -1509,11 +589,12 @@ private void logFinalReadable(LensContext context, Tas ObjectDelta syncDelta = projectionContext.getSyncDelta(); if (syncDelta != null) { hasSyncDelta = true; + break; } } Collection> executedDeltas = context.getExecutedDeltas(); - if (!hasSyncDelta && executedDeltas == null || executedDeltas.isEmpty()) { + if (!hasSyncDelta && executedDeltas.isEmpty()) { // Not worth mentioning return; } @@ -1598,7 +679,7 @@ private void logFinalReadable(LensContext context, Tas } } - if (executedDeltas == null || executedDeltas.isEmpty()) { + if (executedDeltas.isEmpty()) { sb.append("Executed: nothing\n"); } else { sb.append("Executed:\n"); @@ -1617,5 +698,4 @@ private void logFinalReadable(LensContext context, Tas "##############################################################", sb.toString()); } - } diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkAuditHelper.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkAuditHelper.java new file mode 100644 index 00000000000..cc5076beaf2 --- /dev/null +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkAuditHelper.java @@ -0,0 +1,279 @@ +/* + * Copyright (c) 2020 Evolveum and contributors + * + * This work is dual-licensed under the Apache License 2.0 + * and European Union Public License. See LICENSE file for details. + */ + +package com.evolveum.midpoint.model.impl.lens; + +import com.evolveum.midpoint.audit.api.AuditEventRecord; +import com.evolveum.midpoint.audit.api.AuditEventStage; +import com.evolveum.midpoint.audit.api.AuditEventType; +import com.evolveum.midpoint.model.impl.util.AuditHelper; +import com.evolveum.midpoint.model.impl.util.ModelImplUtils; +import com.evolveum.midpoint.prism.PrismContext; +import com.evolveum.midpoint.prism.PrismObject; +import com.evolveum.midpoint.prism.delta.ObjectDelta; +import com.evolveum.midpoint.prism.xml.XmlTypeConverter; +import com.evolveum.midpoint.repo.common.expression.ExpressionFactory; +import com.evolveum.midpoint.repo.common.expression.ExpressionUtil; +import com.evolveum.midpoint.repo.common.expression.ExpressionVariables; +import com.evolveum.midpoint.schema.ObjectDeltaOperation; +import com.evolveum.midpoint.schema.constants.ExpressionConstants; +import com.evolveum.midpoint.schema.result.OperationResult; +import com.evolveum.midpoint.task.api.Task; +import com.evolveum.midpoint.util.exception.*; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; +import com.evolveum.midpoint.xml.ns._public.common.common_3.*; + +import org.apache.commons.lang.StringUtils; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.stereotype.Component; + +import javax.xml.datatype.XMLGregorianCalendar; +import java.util.Collection; +import java.util.List; + +import static java.util.Collections.emptyList; + +/** + * Audit-related responsibilities during clockwork processing. + */ +@Component +public class ClockworkAuditHelper { + + private static final Trace LOGGER = TraceManager.getTrace(ClockworkAuditHelper.class); + + @Autowired private PrismContext prismContext; + @Autowired private AuditHelper auditHelper; + @Autowired private ExpressionFactory expressionFactory; + + // "overallResult" covers the whole clockwork run + // while "result" is - most of the time - related to the current clockwork click + void audit(LensContext context, AuditEventStage stage, Task task, OperationResult result, + OperationResult overallResult) throws SchemaException { + if (context.isLazyAuditRequest()) { + if (stage == AuditEventStage.REQUEST) { + // We skip auditing here, we will do it before execution + } else if (stage == AuditEventStage.EXECUTION) { + if (context.getUnauditedExecutedDeltas().isEmpty()) { + // No deltas, nothing to audit in this wave + return; + } + if (!context.isRequestAudited()) { + auditEvent(context, AuditEventStage.REQUEST, context.getStats().getRequestTimestamp(), false, task, result, overallResult); + } + auditEvent(context, stage, null, false, task, result, overallResult); + } + } else { + auditEvent(context, stage, null, false, task, result, overallResult); + } + } + + /** + * Make sure that at least one execution is audited if a request was already audited. We don't want + * request without execution in the audit logs. + */ + void auditFinalExecution(LensContext context, Task task, OperationResult result, + OperationResult overallResult) throws SchemaException { + if (context.isRequestAudited() && !context.isExecutionAudited()) { + auditEvent(context, AuditEventStage.EXECUTION, null, true, task, result, overallResult); + } + } + + // "overallResult" covers the whole clockwork run + // while "result" is - most of the time - related to the current clockwork click + // + // We provide "result" here just for completeness - if any of the called methods would like to record to it. + void auditEvent(LensContext context, AuditEventStage stage, + XMLGregorianCalendar timestamp, boolean alwaysAudit, Task task, OperationResult result, + OperationResult overallResult) throws SchemaException { + + PrismObject primaryObject; + ObjectDelta primaryDelta; + if (context.getFocusContext() != null) { + primaryObject = context.getFocusContext().getObjectOld(); + if (primaryObject == null) { + primaryObject = context.getFocusContext().getObjectNew(); + } + primaryDelta = context.getFocusContext().getDelta(); + } else { + Collection projectionContexts = context.getProjectionContexts(); + if (projectionContexts == null || projectionContexts.isEmpty()) { + throw new IllegalStateException("No focus and no projections in "+context); + } + if (projectionContexts.size() > 1) { + throw new IllegalStateException("No focus and more than one projection in "+context); + } + LensProjectionContext projection = projectionContexts.iterator().next(); + primaryObject = projection.getObjectOld(); + if (primaryObject == null) { + primaryObject = projection.getObjectNew(); + } + primaryDelta = projection.getDelta(); + } + + AuditEventType eventType; + if (primaryDelta == null) { + eventType = AuditEventType.SYNCHRONIZATION; + } else if (primaryDelta.isAdd()) { + eventType = AuditEventType.ADD_OBJECT; + } else if (primaryDelta.isModify()) { + eventType = AuditEventType.MODIFY_OBJECT; + } else if (primaryDelta.isDelete()) { + eventType = AuditEventType.DELETE_OBJECT; + } else { + throw new IllegalStateException("Unknown state of delta "+primaryDelta); + } + + AuditEventRecord auditRecord = new AuditEventRecord(eventType, stage); + auditRecord.setRequestIdentifier(context.getRequestIdentifier()); + + boolean recordResourceOids; + List propertiesToRecord; + SystemConfigurationType config = context.getSystemConfigurationType(); + if (config != null && config.getAudit() != null && config.getAudit().getEventRecording() != null) { + SystemConfigurationAuditEventRecordingType eventRecording = config.getAudit().getEventRecording(); + recordResourceOids = Boolean.TRUE.equals(eventRecording.isRecordResourceOids()); + propertiesToRecord = eventRecording.getProperty(); + } else { + recordResourceOids = false; + propertiesToRecord = emptyList(); + } + + if (primaryObject != null) { + auditRecord.setTarget(primaryObject, prismContext); + if (recordResourceOids) { + if (primaryObject.getRealValue() instanceof FocusType) { + FocusType focus = (FocusType) primaryObject.getRealValue(); + for (ObjectReferenceType shadowRef : focus.getLinkRef()) { + LensProjectionContext projectionContext = context.findProjectionContextByOid(shadowRef.getOid()); + if (projectionContext != null && StringUtils.isNotBlank(projectionContext.getResourceOid())) { + auditRecord.addResourceOid(projectionContext.getResourceOid()); + } + } + } else if (primaryObject.getRealValue() instanceof ShadowType) { + ObjectReferenceType resource = ((ShadowType) primaryObject.getRealValue()).getResourceRef(); + if (resource != null && resource.getOid() != null) { + auditRecord.addResourceOid(resource.getOid()); + } + } + } + } + + auditRecord.setChannel(context.getChannel()); + + // This is a brutal hack -- FIXME: create some "compute in-depth preview" method on operation result + OperationResult clone = overallResult.clone(2, false); + for (OperationResult subresult : clone.getSubresults()) { + subresult.computeStatusIfUnknown(); + } + clone.computeStatus(); + + if (stage == AuditEventStage.REQUEST) { + Collection> clonedDeltas = ObjectDeltaOperation.cloneDeltaCollection(context.getPrimaryChanges()); + checkNamesArePresent(clonedDeltas, primaryObject); + auditRecord.addDeltas(clonedDeltas); + if (auditRecord.getTarget() == null) { + auditRecord.setTarget(ModelImplUtils.determineAuditTargetDeltaOps(clonedDeltas, context.getPrismContext())); + } + } else if (stage == AuditEventStage.EXECUTION) { + auditRecord.setOutcome(clone.getStatus()); + Collection> unauditedExecutedDeltas = context.getUnauditedExecutedDeltas(); + if (!alwaysAudit && (unauditedExecutedDeltas == null || unauditedExecutedDeltas.isEmpty())) { + // No deltas, nothing to audit in this wave + return; + } + Collection> clonedDeltas = ObjectDeltaOperation.cloneCollection(unauditedExecutedDeltas); + checkNamesArePresent(clonedDeltas, primaryObject); + auditRecord.addDeltas(clonedDeltas); + } else { + throw new IllegalStateException("Unknown audit stage "+stage); + } + + if (timestamp != null) { + auditRecord.setTimestamp(XmlTypeConverter.toMillis(timestamp)); + } + + addRecordMessage(auditRecord, clone.getMessage()); + + for (SystemConfigurationAuditEventRecordingPropertyType property : propertiesToRecord) { + String name = property.getName(); + if (StringUtils.isBlank(name)) { + throw new IllegalArgumentException("Name of SystemConfigurationAuditEventRecordingPropertyType is empty or null in " + property); + } + ExpressionType expression = property.getExpression(); + if (expression != null) { + ExpressionVariables variables = new ExpressionVariables(); + variables.put(ExpressionConstants.VAR_TARGET, primaryObject, PrismObject.class); + variables.put(ExpressionConstants.VAR_AUDIT_RECORD, auditRecord, AuditEventRecord.class); + String shortDesc = "value for custom column of audit table"; + try { + Collection values = ExpressionUtil.evaluateStringExpression(variables, prismContext, expression, context.getPrivilegedExpressionProfile(), expressionFactory, shortDesc, task, result); + if (values != null && !values.isEmpty()) { + if (values.size() > 1) { + throw new IllegalArgumentException("Collection of expression result contains more as one value"); + } + auditRecord.getCustomColumnProperty().put(name, values.iterator().next()); + } + } catch (CommonException e) { + LOGGER.error("Couldn't evaluate Expression " + expression.toString(), e); + } + } + } + + auditHelper.audit(auditRecord, context.getNameResolver(), task, result); + + if (stage == AuditEventStage.EXECUTION) { + // We need to clean up so these deltas will not be audited again in next wave + context.markExecutedDeltasAudited(); + context.setExecutionAudited(true); + } else { + assert stage == AuditEventStage.REQUEST; + context.setRequestAudited(true); + } + } + + private void checkNamesArePresent(Collection> deltas, PrismObject primaryObject) { + if (primaryObject != null) { + for (ObjectDeltaOperation delta : deltas) { + if (delta.getObjectName() == null) { + delta.setObjectName(primaryObject.getName()); + } + } + } + } + + /** + * Adds a message to the record by pulling the messages from individual delta results. + */ + private void addRecordMessage(AuditEventRecord auditRecord, String message) { + if (auditRecord.getMessage() != null) { + return; + } + if (!StringUtils.isEmpty(message)) { + auditRecord.setMessage(message); + return; + } + Collection> deltas = auditRecord.getDeltas(); + if (deltas == null || deltas.isEmpty()) { + return; + } + StringBuilder sb = new StringBuilder(); + for (ObjectDeltaOperation delta: deltas) { + OperationResult executionResult = delta.getExecutionResult(); + if (executionResult != null) { + String deltaMessage = executionResult.getMessage(); + if (!StringUtils.isEmpty(deltaMessage)) { + if (sb.length() != 0) { + sb.append("; "); + } + sb.append(deltaMessage); + } + } + } + auditRecord.setMessage(sb.toString()); + } +} diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkConflictResolver.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkConflictResolver.java new file mode 100644 index 00000000000..a0495883f03 --- /dev/null +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkConflictResolver.java @@ -0,0 +1,223 @@ +/* + * Copyright (c) 2020 Evolveum and contributors + * + * This work is dual-licensed under the Apache License 2.0 + * and European Union Public License. See LICENSE file for details. + */ + +package com.evolveum.midpoint.model.impl.lens; + +import com.evolveum.midpoint.model.api.ModelExecuteOptions; +import com.evolveum.midpoint.model.api.ProgressInformation; +import com.evolveum.midpoint.model.api.hooks.HookOperationMode; +import com.evolveum.midpoint.model.impl.util.ModelImplUtils; +import com.evolveum.midpoint.prism.PrismObject; +import com.evolveum.midpoint.repo.api.ConflictWatcher; +import com.evolveum.midpoint.repo.api.PreconditionViolationException; +import com.evolveum.midpoint.repo.api.RepositoryService; +import com.evolveum.midpoint.schema.result.OperationResult; +import com.evolveum.midpoint.task.api.Task; +import com.evolveum.midpoint.util.exception.*; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; +import com.evolveum.midpoint.xml.ns._public.common.common_3.*; + +import org.jetbrains.annotations.NotNull; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.beans.factory.annotation.Qualifier; +import org.springframework.stereotype.Component; + +import java.util.ArrayList; + +import static com.evolveum.midpoint.model.api.ProgressInformation.ActivityType.WAITING; +import static com.evolveum.midpoint.model.api.ProgressInformation.StateType.EXITING; + +import static org.apache.commons.collections4.CollectionUtils.emptyIfNull; +import static org.apache.commons.lang3.ObjectUtils.defaultIfNull; + +/** + * Resolves conflicts occurring during clockwork processing (multiple threads modifying the same focus). + */ +@Component +public class ClockworkConflictResolver { + + private static final Trace LOGGER = TraceManager.getTrace(ClockworkConflictResolver.class); + + @Autowired private Clockwork clockwork; + @Autowired private ContextFactory contextFactory; + @Autowired @Qualifier("cacheRepositoryService") private transient RepositoryService repositoryService; + + private static final int DEFAULT_MAX_CONFLICT_RESOLUTION_ATTEMPTS = 1; // synchronize with common-core-3.xsd + private static final int DEFAULT_CONFLICT_RESOLUTION_DELAY_UNIT = 5000; // synchronize with common-core-3.xsd + private static final int MAX_PRECONDITION_CONFLICT_RESOLUTION_ATTEMPTS = 3; + + static class Context { + private boolean focusConflictPresent; + private ConflictResolutionType resolutionPolicy; + } + + void createConflictWatcherOnStart(LensContext context) { + if (context.getFocusContext() != null && context.getFocusContext().getOid() != null) { + context.createAndRegisterFocusConflictWatcher(context.getFocusContext().getOid(), repositoryService); + } + } + + void createConflictWatcherAfterFocusAddition(LensContext context, String oid, String expectedVersion) { + // The watcher can already exist; if the OID was pre-existing in the object. + if (context.getFocusConflictWatcher() == null) { + ConflictWatcher watcher = context.createAndRegisterFocusConflictWatcher(oid, repositoryService); + watcher.setExpectedVersion(expectedVersion); + } + } + + void unregisterConflictWatcher(LensContext context) { + context.unregisterConflictWatcher(repositoryService); + } + + void checkFocusConflicts(LensContext context, Context resolutionContext, OperationResult result) { + resolutionContext.resolutionPolicy = ModelImplUtils.getConflictResolution(context); + ConflictWatcher watcher = context.getFocusConflictWatcher(); + if (watcher != null && resolutionContext.resolutionPolicy != null && + resolutionContext.resolutionPolicy.getAction() != ConflictResolutionActionType.NONE && + repositoryService.hasConflict(watcher, result)) { + LOGGER.debug("Found modify-modify conflict on {}", watcher); + resolutionContext.focusConflictPresent = true; + } else { + resolutionContext.focusConflictPresent = false; + } + } + + HookOperationMode resolveFocusConflictIfPresent(LensContext context, Context resolutionContext, + HookOperationMode finalMode, Task task, OperationResult result) throws CommunicationException, + ObjectNotFoundException, ObjectAlreadyExistsException, PolicyViolationException, SchemaException, + SecurityViolationException, ConfigurationException, ExpressionEvaluationException { + if (resolutionContext.focusConflictPresent) { + assert finalMode == HookOperationMode.FOREGROUND; + return resolveFocusConflict(context, resolutionContext.resolutionPolicy, task, result); + } else { + if (context.getConflictResolutionAttemptNumber() > 0) { + LOGGER.info("Resolved update conflict on attempt number {}", context.getConflictResolutionAttemptNumber()); + } + return finalMode; + } + } + + private HookOperationMode resolveFocusConflict(LensContext context, + ConflictResolutionType resolutionPolicy, Task task, OperationResult result) + throws SchemaException, ObjectNotFoundException, ExpressionEvaluationException, ConfigurationException, + CommunicationException, SecurityViolationException, PolicyViolationException, ObjectAlreadyExistsException { + if (resolutionPolicy == null || resolutionPolicy.getAction() == ConflictResolutionActionType.NONE) { + return HookOperationMode.FOREGROUND; + } + PrismObject focusObject = context.getFocusContext() != null ? context.getFocusContext().getObjectAny() : null; + ModelExecuteOptions options = new ModelExecuteOptions(); + switch (resolutionPolicy.getAction()) { + case FAIL: throw new SystemException("Conflict detected while updating " + focusObject); + case LOG: + LOGGER.warn("Conflict detected while updating {}", focusObject); + return HookOperationMode.FOREGROUND; + case RECOMPUTE: + break; + case RECONCILE: + options.setReconcile(); + break; + default: + throw new IllegalStateException("Unsupported conflict resolution action: " + resolutionPolicy.getAction()); + } + + // so, recompute is the action + LOGGER.debug("CONFLICT: Conflict detected while updating {}, recomputing (options={})", focusObject, options); + + if (context.getFocusContext() == null) { + LOGGER.warn("No focus context, not possible to resolve conflict by focus recomputation"); // should really never occur + return HookOperationMode.FOREGROUND; + } + String oid = context.getFocusContext().getOid(); + if (oid == null) { + LOGGER.warn("No focus OID, not possible to resolve conflict by focus recomputation"); // should really never occur + return HookOperationMode.FOREGROUND; + } + Class focusClass = context.getFocusContext().getObjectTypeClass(); + if (focusClass == null) { + LOGGER.warn("Focus class not known, not possible to resolve conflict by focus recomputation"); // should really never occur + return HookOperationMode.FOREGROUND; + } + if (TaskType.class.isAssignableFrom(focusClass)) { + return HookOperationMode.FOREGROUND; // this is actually quite expected, so don't bother anyone with that + } + if (!FocusType.class.isAssignableFrom(focusClass)) { + LOGGER.warn("Focus is not of FocusType (it is {}); not possible to resolve conflict by focus recomputation", focusClass.getName()); + return HookOperationMode.FOREGROUND; + } + + ConflictResolutionType focusConflictResolution = new ConflictResolutionType(); + focusConflictResolution.setAction(ConflictResolutionActionType.ERROR); + options.setFocusConflictResolution(focusConflictResolution); + + int preconditionAttempts = 0; + while (true) { + + int attemptOld = context.getConflictResolutionAttemptNumber(); + int attemptNew = attemptOld + 1; + boolean shouldExecuteAttempt = shouldExecuteAttempt(resolutionPolicy, attemptNew); + if (!shouldExecuteAttempt) { + LOGGER.warn("CONFLICT: Couldn't resolve conflict even after {} resolution attempt(s), giving up.", attemptOld); + return HookOperationMode.FOREGROUND; + } + + delay(context, resolutionPolicy, attemptNew + preconditionAttempts); + + PrismObject focus = repositoryService.getObject(focusClass, oid, null, result); + LensContext contextNew = contextFactory.createRecomputeContext(focus, options, task, result); + contextNew.setProgressListeners(new ArrayList<>(emptyIfNull(context.getProgressListeners()))); + contextNew.setConflictResolutionAttemptNumber(attemptNew); + + LOGGER.debug("CONFLICT: Recomputing {} as reaction to conflict (options={}, attempts={},{}, readVersion={})", + context.getFocusContext().getHumanReadableName(), options, attemptNew, preconditionAttempts, contextNew.getFocusContext().getObjectReadVersion()); + + try { + + // this is a recursion; but limited to max attempts which should not be a large number + HookOperationMode hookOperationMode = clockwork.run(contextNew, task, result); + + // This may be in fact a give-up after recompute that was not able to cleanly proceed. + LOGGER.debug("CONFLICT: Clean recompute (or give-up) of {} achieved (options={}, attempts={},{})", + context.getFocusContext().getHumanReadableName(), options, attemptNew, preconditionAttempts); + + return hookOperationMode; + + } catch (PreconditionViolationException e) { + preconditionAttempts++; + LOGGER.debug("CONFLICT: Recompute precondition failed (attempt {}, precondition attempt {}), trying again", attemptNew, preconditionAttempts); + if (preconditionAttempts < MAX_PRECONDITION_CONFLICT_RESOLUTION_ATTEMPTS) { + continue; + } + LOGGER.warn("CONFLICT: Couldn't resolve conflict even after {} resolution attempt(s) and {} precondition attempts, giving up.", + attemptOld, preconditionAttempts); + return HookOperationMode.FOREGROUND; + } + } + } + + private boolean shouldExecuteAttempt(@NotNull ConflictResolutionType resolutionPolicy, int attempt) { + int maxAttempts = defaultIfNull(resolutionPolicy.getMaxAttempts(), DEFAULT_MAX_CONFLICT_RESOLUTION_ATTEMPTS); + return attempt <= maxAttempts; + } + + private void delay(LensContext context, @NotNull ConflictResolutionType resolutionPolicy, int attempt) { + long delayRange = defaultIfNull(resolutionPolicy.getDelayUnit(), DEFAULT_CONFLICT_RESOLUTION_DELAY_UNIT) * (1L << attempt); + long delay = (long) (Math.random() * delayRange); + String message = "CONFLICT: Waiting "+delay+" milliseconds before starting conflict resolution (delay exponent: "+attempt+")"; + // TODO convey information about waiting time after some GUI mechanism for displaying it is available + // (showing text messages is currently really ugly) + context.reportProgress(new ProgressInformation(WAITING, EXITING)); + LOGGER.debug(message); + try { + Thread.sleep(delay); + } catch (InterruptedException e) { + // ignore + } + context.reportProgress(new ProgressInformation(WAITING, EXITING)); + } + +} diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkHookHelper.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkHookHelper.java new file mode 100644 index 00000000000..42699f046b9 --- /dev/null +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/ClockworkHookHelper.java @@ -0,0 +1,180 @@ +/* + * Copyright (c) 2020 Evolveum and contributors + * + * This work is dual-licensed under the Apache License 2.0 + * and European Union Public License. See LICENSE file for details. + */ + +package com.evolveum.midpoint.model.impl.lens; + +import com.evolveum.midpoint.model.api.context.ModelContext; +import com.evolveum.midpoint.model.api.hooks.ChangeHook; +import com.evolveum.midpoint.model.api.hooks.HookOperationMode; +import com.evolveum.midpoint.model.api.hooks.HookRegistry; +import com.evolveum.midpoint.model.common.SystemObjectCache; +import com.evolveum.midpoint.model.common.expression.script.ScriptExpression; +import com.evolveum.midpoint.model.common.expression.script.ScriptExpressionFactory; +import com.evolveum.midpoint.model.impl.util.ModelImplUtils; +import com.evolveum.midpoint.prism.PrismContext; +import com.evolveum.midpoint.prism.PrismObject; +import com.evolveum.midpoint.prism.PrismObjectDefinition; +import com.evolveum.midpoint.repo.common.expression.ExpressionFactory; +import com.evolveum.midpoint.repo.common.expression.ExpressionVariables; +import com.evolveum.midpoint.schema.constants.ExpressionConstants; +import com.evolveum.midpoint.schema.constants.ObjectTypes; +import com.evolveum.midpoint.schema.result.OperationResult; +import com.evolveum.midpoint.task.api.Task; +import com.evolveum.midpoint.util.exception.*; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; +import com.evolveum.midpoint.xml.ns._public.common.common_3.*; + +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.stereotype.Component; + +import javax.xml.namespace.QName; + +/** + * Responsible for invoking hooks (both Java and scripting ones). + */ +@Component +public class ClockworkHookHelper { + + private static final Trace LOGGER = TraceManager.getTrace(ClockworkHookHelper.class); + + @Autowired(required = false) private HookRegistry hookRegistry; + @Autowired private PrismContext prismContext; + @Autowired private ExpressionFactory expressionFactory; + @Autowired private ScriptExpressionFactory scriptExpressionFactory; + @Autowired private SystemObjectCache systemObjectCache; + + /** + * Invokes hooks, if there are any. + * + * @return + * - ERROR, if any hook reported error; otherwise returns + * - BACKGROUND, if any hook reported switching to background; otherwise + * - FOREGROUND (if all hooks reported finishing on foreground) + */ + HookOperationMode invokeHooks(LensContext context, Task task, OperationResult result) throws ExpressionEvaluationException, ObjectNotFoundException, SchemaException, PolicyViolationException, CommunicationException, ConfigurationException, SecurityViolationException { + // TODO: following two parts should be merged together in later versions + + // Execute configured scripting hooks + PrismObject systemConfiguration = systemObjectCache.getSystemConfiguration(result); + // systemConfiguration may be null in some tests + if (systemConfiguration != null) { + ModelHooksType modelHooks = systemConfiguration.asObjectable().getModelHooks(); + if (modelHooks != null) { + HookListType changeHooks = modelHooks.getChange(); + if (changeHooks != null) { + for (HookType hookType: changeHooks.getHook()) { + String shortDesc; + if (hookType.getName() != null) { + shortDesc = "hook '"+hookType.getName()+"'"; + } else { + shortDesc = "scripting hook in system configuration"; + } + if (hookType.isEnabled() != null && !hookType.isEnabled()) { + // Disabled hook, skip + continue; + } + if (hookType.getState() != null) { + if (!context.getState().toModelStateType().equals(hookType.getState())) { + continue; + } + } + if (hookType.getFocusType() != null) { + if (context.getFocusContext() == null) { + continue; + } + QName hookFocusTypeQname = hookType.getFocusType(); + ObjectTypes hookFocusType = ObjectTypes.getObjectTypeFromTypeQName(hookFocusTypeQname); + if (hookFocusType == null) { + throw new SchemaException("Unknown focus type QName "+hookFocusTypeQname+" in "+shortDesc); + } + Class focusClass = context.getFocusClass(); + Class hookFocusClass = hookFocusType.getClassDefinition(); + if (!hookFocusClass.isAssignableFrom(focusClass)) { + continue; + } + } + + ScriptExpressionEvaluatorType scriptExpressionEvaluatorType = hookType.getScript(); + if (scriptExpressionEvaluatorType == null) { + continue; + } + try { + evaluateScriptingHook(context, scriptExpressionEvaluatorType, shortDesc, task, result); + } catch (ExpressionEvaluationException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new ExpressionEvaluationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } catch (ObjectNotFoundException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new ObjectNotFoundException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } catch (SchemaException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new SchemaException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } catch (CommunicationException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new CommunicationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } catch (ConfigurationException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new ConfigurationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } catch (SecurityViolationException e) { + LOGGER.error("Evaluation of {} failed: {}", shortDesc, e.getMessage(), e); + throw new SecurityViolationException("Evaluation of "+shortDesc+" failed: "+e.getMessage(), e); + } + } + } + } + } + + // Execute registered Java hooks + HookOperationMode resultMode = HookOperationMode.FOREGROUND; + if (hookRegistry != null) { + for (ChangeHook hook : hookRegistry.getAllChangeHooks()) { + HookOperationMode mode = hook.invoke(context, task, result); + if (mode == HookOperationMode.ERROR) { + resultMode = HookOperationMode.ERROR; + } else if (mode == HookOperationMode.BACKGROUND) { + if (resultMode != HookOperationMode.ERROR) { + resultMode = HookOperationMode.BACKGROUND; + } + } + } + } + return resultMode; + } + + private void evaluateScriptingHook(LensContext context, + ScriptExpressionEvaluatorType scriptExpressionEvaluatorType, String shortDesc, Task task, OperationResult result) + throws ExpressionEvaluationException, ObjectNotFoundException, SchemaException, CommunicationException, ConfigurationException, SecurityViolationException { + + LOGGER.trace("Evaluating {}", shortDesc); + // TODO: it would be nice to cache this + // null output definition: this script has no output + ScriptExpression scriptExpression = scriptExpressionFactory.createScriptExpression(scriptExpressionEvaluatorType, null, context.getPrivilegedExpressionProfile(), expressionFactory, shortDesc, task, result); + + ExpressionVariables variables = new ExpressionVariables(); + variables.put(ExpressionConstants.VAR_PRISM_CONTEXT, prismContext, PrismContext.class); + variables.put(ExpressionConstants.VAR_MODEL_CONTEXT, context, ModelContext.class); + LensFocusContext focusContext = context.getFocusContext(); + if (focusContext != null) { + variables.put(ExpressionConstants.VAR_FOCUS, focusContext.getObjectAny(), focusContext.getObjectDefinition()); + } else { + PrismObjectDefinition def = prismContext.getSchemaRegistry().findObjectDefinitionByCompileTimeClass(ObjectType.class); + variables.put(ExpressionConstants.VAR_FOCUS, null, def); + } + + ModelImplUtils.evaluateScript(scriptExpression, context, variables, false, shortDesc, task, result); + LOGGER.trace("Finished evaluation of {}", shortDesc); + } + + void invokePreview(LensContext context, Task task, OperationResult result) { + if (hookRegistry != null) { + for (ChangeHook hook : hookRegistry.getAllChangeHooks()) { + hook.invokePreview(context, task, result); + } + } + } +} diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/LensContext.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/LensContext.java index 1909807b869..49678098608 100644 --- a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/LensContext.java +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/LensContext.java @@ -17,6 +17,7 @@ import com.evolveum.midpoint.prism.PrismContext; import com.evolveum.midpoint.prism.PrismObject; import com.evolveum.midpoint.prism.delta.DeltaSetTriple; +import com.evolveum.midpoint.prism.delta.ItemDelta; import com.evolveum.midpoint.prism.delta.ObjectDelta; import com.evolveum.midpoint.prism.polystring.PolyString; import com.evolveum.midpoint.provisioning.api.ProvisioningService; @@ -30,10 +31,7 @@ import com.evolveum.midpoint.schema.util.MiscSchemaUtil; import com.evolveum.midpoint.schema.util.ObjectDeltaSchemaLevelUtil; import com.evolveum.midpoint.task.api.Task; -import com.evolveum.midpoint.util.DebugUtil; -import com.evolveum.midpoint.util.LocalizableMessage; -import com.evolveum.midpoint.util.QNameUtil; -import com.evolveum.midpoint.util.TreeNode; +import com.evolveum.midpoint.util.*; import com.evolveum.midpoint.util.exception.*; import com.evolveum.midpoint.util.logging.Trace; import com.evolveum.midpoint.util.logging.TraceManager; @@ -106,9 +104,7 @@ public enum ExportType { private Class focusClass; - private boolean lazyAuditRequest = false; // should be the request audited - // just before the execution is - // audited? + private boolean lazyAuditRequest = false; // should be the request audited just before the execution is audited? private boolean requestAudited = false; // was the request audited? private boolean executionAudited = false; // was the execution audited? private LensContextStatsType stats = new LensContextStatsType(); @@ -153,12 +149,12 @@ public enum ExportType { /** * Current wave of computation and execution. */ - int projectionWave = 0; + private int projectionWave = 0; /** * Current wave of execution. */ - int executionWave = 0; + private int executionWave = 0; private String triggeredResourceOid; @@ -467,6 +463,69 @@ public void rot(String reason) { } } + /** + * Force recompute for the next execution wave. Recompute only those contexts that were changed. + * This is more intelligent than rot() + */ + void rotIfNeeded() throws SchemaException { + Holder rotHolder = new Holder<>(false); + rotProjectionContextsIfNeeded(rotHolder); + rotFocusContextIfNeeded(rotHolder); + if (rotHolder.getValue()) { + setFresh(false); + } + } + + private void rotProjectionContextsIfNeeded(Holder rotHolder) throws SchemaException { + for (LensProjectionContext projectionContext: projectionContexts) { + if (projectionContext.getWave() != executionWave) { + LOGGER.trace("Context rot: projection {} NOT rotten because of wrong wave number", projectionContext); + } else { + ObjectDelta execDelta = projectionContext.getExecutableDelta(); + if (isShadowDeltaSignificant(execDelta)) { + LOGGER.debug("Context rot: projection {} rotten because of executable delta {}", projectionContext, execDelta); + projectionContext.setFresh(false); + projectionContext.setFullShadow(false); + rotHolder.setValue(true); + // Propagate to higher-order projections + for (LensProjectionContext relCtx : LensUtil.findRelatedContexts(this, projectionContext)) { + relCtx.setFresh(false); + relCtx.setFullShadow(false); + } + } else { + LOGGER.trace("Context rot: projection {} NOT rotten because no delta", projectionContext); + } + } + } + } + + private

boolean isShadowDeltaSignificant(ObjectDelta

delta) { + if (delta == null || delta.isEmpty()) { + return false; + } + if (delta.isAdd() || delta.isDelete()) { + return true; + } else { + Collection> attrDeltas = delta.findItemDeltasSubPath(ShadowType.F_ATTRIBUTES); + return attrDeltas != null && !attrDeltas.isEmpty(); + } + } + + private void rotFocusContextIfNeeded(Holder rotHolder) + throws SchemaException { + if (focusContext != null) { + ObjectDelta execDelta = focusContext.getWaveDelta(executionWave); + if (execDelta != null && !execDelta.isEmpty()) { + LOGGER.debug("Context rot: context rotten because of focus execution delta {}", execDelta); + rotHolder.setValue(true); + } + if (rotHolder.getValue()) { + // It is OK to refresh focus all the time there was any change. This is cheap. + focusContext.setFresh(false); + } + } + } + public String getChannel() { return channel; } @@ -658,23 +717,24 @@ public void replacePrimaryFocusDeltas(List> deltas) throws Schema /** * Returns all executed deltas, user and all accounts. */ - public Collection> getExecutedDeltas() throws SchemaException { + @NotNull + public Collection> getExecutedDeltas() { return getExecutedDeltas(null); } /** * Returns all executed deltas, user and all accounts. */ - public Collection> getUnauditedExecutedDeltas() - throws SchemaException { + @NotNull + public Collection> getUnauditedExecutedDeltas() { return getExecutedDeltas(false); } /** * Returns all executed deltas, user and all accounts. */ - Collection> getExecutedDeltas(Boolean audited) - throws SchemaException { + @NotNull + private Collection> getExecutedDeltas(Boolean audited) { Collection> executedDeltas = new ArrayList<>(); if (focusContext != null) { executedDeltas.addAll(focusContext.getExecutedDeltas(audited)); @@ -683,7 +743,7 @@ Collection> getExecutedDeltas(Boolean executedDeltas.addAll(projCtx.getExecutedDeltas(audited)); } if (audited == null) { - executedDeltas.addAll((Collection>) getRottenExecutedDeltas()); + executedDeltas.addAll(getRottenExecutedDeltas()); } return executedDeltas; } @@ -1421,18 +1481,18 @@ public void setConflictResolutionAttemptNumber(int conflictResolutionAttemptNumb this.conflictResolutionAttemptNumber = conflictResolutionAttemptNumber; } - public ConflictWatcher getFocusConflictWatcher() { + ConflictWatcher getFocusConflictWatcher() { return focusConflictWatcher; } - public ConflictWatcher createAndRegisterFocusConflictWatcher(@NotNull String oid, RepositoryService repositoryService) { + ConflictWatcher createAndRegisterFocusConflictWatcher(@NotNull String oid, RepositoryService repositoryService) { if (focusConflictWatcher != null) { throw new IllegalStateException("Focus conflict watcher defined twice"); } return focusConflictWatcher = repositoryService.createAndRegisterConflictWatcher(oid); } - public void unregisterConflictWatchers(RepositoryService repositoryService) { + void unregisterConflictWatcher(RepositoryService repositoryService) { if (focusConflictWatcher != null) { repositoryService.unregisterConflictWatcher(focusConflictWatcher); focusConflictWatcher = null; diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/OperationExecutionRecorder.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/OperationExecutionRecorder.java new file mode 100644 index 00000000000..1131e63fa65 --- /dev/null +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/lens/OperationExecutionRecorder.java @@ -0,0 +1,324 @@ +/* + * Copyright (c) 2020 Evolveum and contributors + * + * This work is dual-licensed under the Apache License 2.0 + * and European Union Public License. See LICENSE file for details. + */ + +package com.evolveum.midpoint.model.impl.lens; + +import java.util.*; +import javax.xml.datatype.XMLGregorianCalendar; + +import org.apache.commons.lang3.Validate; +import org.jetbrains.annotations.NotNull; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.beans.factory.annotation.Qualifier; +import org.springframework.stereotype.Component; + +import com.evolveum.midpoint.common.Clock; +import com.evolveum.midpoint.model.common.SystemObjectCache; +import com.evolveum.midpoint.prism.PrismContainerValue; +import com.evolveum.midpoint.prism.PrismContext; +import com.evolveum.midpoint.prism.PrismObject; +import com.evolveum.midpoint.prism.delta.ChangeType; +import com.evolveum.midpoint.prism.delta.ItemDelta; +import com.evolveum.midpoint.prism.delta.ObjectDelta; +import com.evolveum.midpoint.prism.util.CloneUtil; +import com.evolveum.midpoint.prism.xml.XmlTypeConverter; +import com.evolveum.midpoint.repo.api.RepositoryService; +import com.evolveum.midpoint.schema.ObjectDeltaOperation; +import com.evolveum.midpoint.schema.result.OperationResult; +import com.evolveum.midpoint.schema.util.ObjectTypeUtil; +import com.evolveum.midpoint.task.api.RunningTask; +import com.evolveum.midpoint.task.api.Task; +import com.evolveum.midpoint.util.DebugUtil; +import com.evolveum.midpoint.util.exception.ObjectAlreadyExistsException; +import com.evolveum.midpoint.util.exception.ObjectNotFoundException; +import com.evolveum.midpoint.util.exception.SchemaException; +import com.evolveum.midpoint.util.logging.LoggingUtils; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; +import com.evolveum.midpoint.xml.ns._public.common.common_3.*; + +/** + * Responsible for maintaining "operation execution" records. + */ +@Component +public class OperationExecutionRecorder { + + private static final Trace LOGGER = TraceManager.getTrace(OperationExecutionRecorder.class); + + @Autowired private Clock clock; + @Autowired private SystemObjectCache systemObjectCache; + @Autowired private PrismContext prismContext; + @Autowired @Qualifier("cacheRepositoryService") private transient RepositoryService repositoryService; + + private static final int DEFAULT_NUMBER_OF_RESULTS_TO_KEEP = 5; + + void recordOperationExecution(LensContext context, Throwable clockworkException, + Task task, OperationResult result) { + boolean skip = context.getInternalsConfiguration() != null && + context.getInternalsConfiguration().getOperationExecutionRecording() != null && + Boolean.TRUE.equals(context.getInternalsConfiguration().getOperationExecutionRecording().isSkip()); + if (!skip) { + XMLGregorianCalendar now = clock.currentTimeXMLGregorianCalendar(); + try { + LOGGER.trace("recordOperationExecution starting; task = {}, clockworkException = {}", task, clockworkException); + boolean opRecordedIntoFocus = recordFocusOperationExecution(context, now, clockworkException, task, result); + for (LensProjectionContext projectionContext : context.getProjectionContexts()) { + Throwable exceptionToProjection; + if (clockworkException != null && !opRecordedIntoFocus && projectionContext.isSynchronizationSource()) { + // We need to record the exception somewhere. Because we were not able to put it into focus, + // we have to do it into sync-source projection. + exceptionToProjection = clockworkException; + } else { + exceptionToProjection = null; + } + recordProjectionOperationExecution(context, projectionContext, now, exceptionToProjection, task, result); + } + } catch (Throwable t) { + LoggingUtils.logUnexpectedException(LOGGER, "Couldn't record operation execution. Model context:\n{}", t, + context.debugDump()); + // Let us ignore this for the moment. It should not have happened, sure. But it's not that crucial. + // Administrator will be able to learn about the problem from the log. + } + } else { + LOGGER.trace("Skipping operation execution recording (as set in system configuration)"); + } + } + + /** + * @return true if the operation execution was recorded (or would be recorded, but skipped because of the configuration) + */ + private boolean recordFocusOperationExecution(LensContext context, XMLGregorianCalendar now, + Throwable clockworkException, Task task, OperationResult result) + throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { + LensFocusContext focusContext = context.getFocusContext(); + if (focusContext == null || focusContext.isDelete()) { + LOGGER.trace("focusContext is null or 'delete', not recording focus operation execution"); + return false; + } + PrismObject objectNew = focusContext.getObjectNew(); + Validate.notNull(objectNew, "No focus object even if the context is not of 'delete' type"); + + //noinspection unchecked + List> executedDeltas = getExecutedDeltas(focusContext, + (Class) objectNew.asObjectable().getClass(), clockworkException, result); + LOGGER.trace("recordFocusOperationExecution: executedDeltas: {}", executedDeltas.size()); + return recordOperationExecution(objectNew, false, executedDeltas, now, context.getChannel(), + getSkipWhenSuccess(context), task, result); + } + + @NotNull + private List> getExecutedDeltas(LensElementContext elementContext, + Class objectClass, Throwable clockworkException, OperationResult result) { + List> executedDeltas; + if (clockworkException != null) { + executedDeltas = new ArrayList<>(elementContext.getExecutedDeltas()); + LensObjectDeltaOperation odo = new LensObjectDeltaOperation<>(); + ObjectDelta primaryDelta = elementContext.getPrimaryDelta(); + if (primaryDelta != null) { + odo.setObjectDelta(primaryDelta); + } else { + ObjectDelta fakeDelta = prismContext.deltaFactory().object().create(objectClass, ChangeType.MODIFY); + odo.setObjectDelta(fakeDelta); + } + odo.setExecutionResult(result); // we rely on the fact that 'result' already contains record of the exception + executedDeltas.add(odo); + } else { + executedDeltas = elementContext.getExecutedDeltas(); + } + return executedDeltas; + } + + private boolean getSkipWhenSuccess(LensContext context) { + return context.getInternalsConfiguration() != null && + context.getInternalsConfiguration().getOperationExecutionRecording() != null && + Boolean.TRUE.equals(context.getInternalsConfiguration().getOperationExecutionRecording().isSkipWhenSuccess()); + } + + private void recordProjectionOperationExecution(LensContext context, + LensProjectionContext projectionContext, XMLGregorianCalendar now, Throwable clockworkException, + Task task, OperationResult result) throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { + PrismObject object = projectionContext.getObjectAny(); + if (object == null) { + return; // this can happen + } + List> executedDeltas = getExecutedDeltas(projectionContext, ShadowType.class, + clockworkException, result); + recordOperationExecution(object, true, executedDeltas, now, + context.getChannel(), getSkipWhenSuccess(context), task, result); + } + + /** + * @return true if the operation execution was recorded (or would be recorded, but skipped because of the configuration) + */ + private boolean recordOperationExecution(PrismObject object, boolean deletedOk, + List> executedDeltas, XMLGregorianCalendar now, + String channel, boolean skipWhenSuccess, Task task, OperationResult result) + throws ObjectAlreadyExistsException, ObjectNotFoundException, SchemaException { + OperationExecutionType operation = new OperationExecutionType(prismContext); + OperationResult summaryResult = new OperationResult("recordOperationExecution"); + String oid = object.getOid(); + for (LensObjectDeltaOperation deltaOperation : executedDeltas) { + operation.getOperation().add(createObjectDeltaOperation(deltaOperation)); + if (deltaOperation.getExecutionResult() != null) { + summaryResult.addSubresult(deltaOperation.getExecutionResult().clone()); // todo eliminate this clone (but beware of modifying the subresult) + } + if (oid == null && deltaOperation.getObjectDelta() != null) { + oid = deltaOperation.getObjectDelta().getOid(); + } + } + if (oid == null) { // e.g. if there is an exception in provisioning.addObject method + LOGGER.trace("recordOperationExecution: skipping because oid is null for object = {}", object); + return false; + } + summaryResult.computeStatus(); + OperationResultStatusType overallStatus = summaryResult.getStatus().createStatusType(); + setOperationContext(operation, overallStatus, now, channel, task); + storeOperationExecution(object, oid, operation, deletedOk, skipWhenSuccess, result); + return true; + } + + private void storeOperationExecution(@NotNull PrismObject object, @NotNull String oid, + @NotNull OperationExecutionType executionToAdd, boolean deletedOk, boolean skipWhenSuccess, OperationResult result) + throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException { + Integer recordsToKeep; + Long deleteBefore; + boolean keepNoExecutions = false; + PrismObject systemConfiguration = systemObjectCache.getSystemConfiguration(result); + if (systemConfiguration != null && systemConfiguration.asObjectable().getCleanupPolicy() != null + && systemConfiguration.asObjectable().getCleanupPolicy().getObjectResults() != null) { + CleanupPolicyType policy = systemConfiguration.asObjectable().getCleanupPolicy().getObjectResults(); + recordsToKeep = policy.getMaxRecords(); + if (recordsToKeep != null && recordsToKeep == 0) { + LOGGER.trace("objectResults.recordsToKeep is 0, will skip storing operationExecutions"); + keepNoExecutions = true; + } + if (policy.getMaxAge() != null) { + XMLGregorianCalendar limit = XmlTypeConverter.addDuration( + XmlTypeConverter.createXMLGregorianCalendar(new Date()), policy.getMaxAge().negate()); + deleteBefore = XmlTypeConverter.toMillis(limit); + } else { + deleteBefore = null; + } + } else { + recordsToKeep = DEFAULT_NUMBER_OF_RESULTS_TO_KEEP; + deleteBefore = null; + } + + String taskOid = executionToAdd.getTaskRef() != null ? executionToAdd.getTaskRef().getOid() : null; + if (executionToAdd.getStatus() == OperationResultStatusType.SUCCESS && skipWhenSuccess) { + // We want to skip writing operationExecution. But let's check if there are some older non-success results + // related to the current task + if (taskOid != null) { + boolean hasNonSuccessFromCurrentTask = object.asObjectable().getOperationExecution().stream() + .anyMatch(oe -> oe.getTaskRef() != null && taskOid.equals(oe.getTaskRef().getOid()) && + oe.getStatus() != OperationResultStatusType.SUCCESS); + if (hasNonSuccessFromCurrentTask) { + LOGGER.trace("Cannot skip OperationExecution recording because there's an older non-success record from the current task"); + } else { + LOGGER.trace("Skipping OperationExecution recording because status is SUCCESS and skipWhenSuccess is true " + + "(and no older non-success records for current task {} exist)", taskOid); + return; + } + } else { + LOGGER.trace("Skipping OperationExecution recording because status is SUCCESS and skipWhenSuccess is true"); + return; + } + } + List executionsToDelete = new ArrayList<>(); + List executions = new ArrayList<>(object.asObjectable().getOperationExecution()); + // delete all executions related to current task and all old ones + for (Iterator iterator = executions.iterator(); iterator.hasNext(); ) { + OperationExecutionType execution = iterator.next(); + boolean isPreviousTaskResult = taskOid != null && execution.getTaskRef() != null && taskOid.equals(execution.getTaskRef().getOid()); + boolean isOld = deleteBefore != null && XmlTypeConverter.toMillis(execution.getTimestamp()) < deleteBefore; + if (isPreviousTaskResult || isOld) { + executionsToDelete.add(execution); + iterator.remove(); + } + } + + // delete all surplus executions + if (recordsToKeep != null && executions.size() > recordsToKeep - 1) { + if (keepNoExecutions) { + executionsToDelete.addAll(executions); + } else { + executions.sort(Comparator.nullsFirst(Comparator.comparing(e -> XmlTypeConverter.toDate(e.getTimestamp())))); + executionsToDelete.addAll(executions.subList(0, executions.size() - (recordsToKeep - 1))); + } + } + // construct and execute the delta + Class objectClass = object.asObjectable().getClass(); + List> deltas = new ArrayList<>(); + if (!keepNoExecutions) { + deltas.add(prismContext.deltaFor(objectClass) + .item(ObjectType.F_OPERATION_EXECUTION) + .add(executionToAdd) + .asItemDelta()); + } + if (!executionsToDelete.isEmpty()) { + deltas.add(prismContext.deltaFor(objectClass) + .item(ObjectType.F_OPERATION_EXECUTION) + .delete(PrismContainerValue.toPcvList(CloneUtil.cloneCollectionMembers(executionsToDelete))) + .asItemDelta()); + } + LOGGER.trace("Operation execution delta:\n{}", DebugUtil.debugDumpLazily(deltas)); + try { + if (!deltas.isEmpty()) { + repositoryService.modifyObject(objectClass, oid, deltas, result); + } + } catch (ObjectNotFoundException e) { + if (!deletedOk) { + throw e; + } else { + LOGGER.trace("Object {} deleted but this was expected.", oid); + result.deleteLastSubresultIfError(); + } + } + } + + private void setOperationContext(OperationExecutionType operation, + OperationResultStatusType overallStatus, XMLGregorianCalendar now, String channel, Task task) { + if (task instanceof RunningTask && ((RunningTask) task).getParentForLightweightAsynchronousTask() != null) { + task = ((RunningTask) task).getParentForLightweightAsynchronousTask(); + } + if (task.isPersistent()) { + operation.setTaskRef(task.getSelfReference()); + } + operation.setStatus(overallStatus); + operation.setInitiatorRef(ObjectTypeUtil.createObjectRef(task.getOwner(), prismContext)); // TODO what if the real initiator is different? (e.g. when executing approved changes) + operation.setChannel(channel); + operation.setTimestamp(now); + } + + private ObjectDeltaOperationType createObjectDeltaOperation(LensObjectDeltaOperation deltaOperation) { + ObjectDeltaOperationType odo; + try { + odo = simplifyOperation(deltaOperation).toLensObjectDeltaOperationType().getObjectDeltaOperation(); + } catch (SchemaException e) { + LoggingUtils.logUnexpectedException(LOGGER, "Couldn't create operation information", e); + odo = new ObjectDeltaOperationType(); + OperationResult r = new OperationResult(Clockwork.class.getName() + ".createObjectDeltaOperation"); + r.recordFatalError("Couldn't create operation information: " + e.getMessage(), e); + odo.setExecutionResult(r.createOperationResultType()); + } + return odo; + } + + private LensObjectDeltaOperation simplifyOperation(ObjectDeltaOperation operation) { + LensObjectDeltaOperation rv = new LensObjectDeltaOperation<>(); + rv.setObjectDelta(simplifyDelta(operation.getObjectDelta())); + rv.setExecutionResult(OperationResult.keepRootOnly(operation.getExecutionResult())); + rv.setObjectName(operation.getObjectName()); + rv.setResourceName(operation.getResourceName()); + rv.setResourceOid(operation.getResourceOid()); + return rv; + } + + private ObjectDelta simplifyDelta(ObjectDelta delta) { + return prismContext.deltaFactory().object().create(delta.getObjectTypeClass(), delta.getChangeType()); + } +} diff --git a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/util/AuditHelper.java b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/util/AuditHelper.java index fb9adacbe37..6f1b9c01ae3 100644 --- a/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/util/AuditHelper.java +++ b/model/model-impl/src/main/java/com/evolveum/midpoint/model/impl/util/AuditHelper.java @@ -22,6 +22,8 @@ import com.evolveum.midpoint.schema.util.ObjectDeltaSchemaLevelUtil; import com.evolveum.midpoint.task.api.Task; import com.evolveum.midpoint.util.exception.ObjectNotFoundException; +import com.evolveum.midpoint.util.logging.Trace; +import com.evolveum.midpoint.util.logging.TraceManager; import com.evolveum.midpoint.xml.ns._public.common.common_3.ObjectType; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.beans.factory.annotation.Qualifier; @@ -30,6 +32,7 @@ import java.util.Collection; import static com.evolveum.midpoint.schema.util.ObjectDeltaSchemaLevelUtil.resolveNames; +import static com.evolveum.midpoint.util.MiscUtil.emptyIfNull; /** * Uses cache repository service to resolve object names. @@ -37,6 +40,8 @@ @Component public class AuditHelper { + private static final Trace LOGGER = TraceManager.getTrace(AuditHelper.class); + @Autowired private AuditService auditService; @Autowired private PrismContext prismContext; @Autowired private SchemaHelper schemaHelper; @@ -44,49 +49,65 @@ public class AuditHelper { @Qualifier("cacheRepositoryService") private RepositoryService repositoryService; + private static final String OP_AUDIT = AuditHelper.class.getName() + ".audit"; + private static final String OP_RESOLVE_NAME = AuditHelper.class.getName() + ".resolveName"; + /** * @param externalNameResolver Name resolver that should be tried first. It should be fast. If it returns null it means * "I don't know". */ public void audit(AuditEventRecord record, ObjectDeltaSchemaLevelUtil.NameResolver externalNameResolver, Task task, OperationResult parentResult) { - // TODO we could obtain names for objects that were deleted e.g. from the lens context (MID-5501) - if (record.getDeltas() != null) { - for (ObjectDeltaOperation objectDeltaOperation : record.getDeltas()) { - ObjectDelta delta = objectDeltaOperation.getObjectDelta(); - ObjectDeltaSchemaLevelUtil.NameResolver nameResolver = (objectClass, oid) -> { - OperationResult result = parentResult.subresult(AuditHelper.class.getName() + ".resolveName") - .setMinor() - .build(); - try { - if (record.getNonExistingReferencedObjects().contains(oid)) { - // This information could come from upper layers (not now, but maybe in the future). - return null; - } - if (externalNameResolver != null) { - PolyString externallyResolvedName = externalNameResolver.getName(objectClass, oid); - if (externallyResolvedName != null) { - return externallyResolvedName; - } + OperationResult result = parentResult.subresult(OP_AUDIT) + .setMinor() + .build(); + try { + LOGGER.trace("Auditing the record:\n{}", record.debugDumpLazily()); + resolveNamesInDeltas(record, externalNameResolver, result); + auditService.audit(record, task); + } catch (Throwable t) { + result.recordFatalError(t); + throw t; + } finally { + result.computeStatusIfUnknown(); + } + } + + private void resolveNamesInDeltas(AuditEventRecord record, ObjectDeltaSchemaLevelUtil.NameResolver externalNameResolver, + OperationResult parentResult) { + for (ObjectDeltaOperation objectDeltaOperation : emptyIfNull(record.getDeltas())) { + ObjectDelta delta = objectDeltaOperation.getObjectDelta(); + ObjectDeltaSchemaLevelUtil.NameResolver nameResolver = (objectClass, oid) -> { + OperationResult result = parentResult.subresult(OP_RESOLVE_NAME) + .setMinor() + .build(); + try { + if (record.getNonExistingReferencedObjects().contains(oid)) { + // This information could come from upper layers (not now, but maybe in the future). + return null; + } + if (externalNameResolver != null) { + PolyString externallyResolvedName = externalNameResolver.getName(objectClass, oid); + if (externallyResolvedName != null) { + return externallyResolvedName; } - // we use only cache-compatible options here, in order to utilize the local or global repository cache - Collection> options = schemaHelper.getOperationOptionsBuilder() - .allowNotFound().build(); - PrismObject object = repositoryService.getObject(objectClass, oid, options, result); - return object.getName(); - } catch (ObjectNotFoundException e) { - record.addNonExistingReferencedObject(oid); - return null; // we will NOT record an error here - } catch (Throwable t) { - result.recordFatalError(t.getMessage(), t); - throw t; - } finally { - result.computeStatusIfUnknown(); } - }; - resolveNames(delta, nameResolver, prismContext); - } + // we use only cache-compatible options here, in order to utilize the local or global repository cache + Collection> options = schemaHelper.getOperationOptionsBuilder() + .allowNotFound().build(); + PrismObject object = repositoryService.getObject(objectClass, oid, options, result); + return object.getName(); + } catch (ObjectNotFoundException e) { + record.addNonExistingReferencedObject(oid); + return null; // we will NOT record an error here + } catch (Throwable t) { + result.recordFatalError(t); + throw t; + } finally { + result.computeStatusIfUnknown(); + } + }; + resolveNames(delta, nameResolver, prismContext); } - auditService.audit(record, task); } }