Skip to content

Commit

Permalink
Rules logging sub category for each rule engine and ruleset (openremo…
Browse files Browse the repository at this point in the history
…te#1132)

* Added logging sub category for each rule engine and ruleset deployment (Closes openremote#1126)
richturner authored Nov 7, 2023
1 parent 22a03b9 commit 2699cbc
Showing 14 changed files with 190 additions and 287 deletions.
Original file line number Diff line number Diff line change
@@ -4,41 +4,48 @@
import org.jeasy.rules.core.RuleBuilder;
import org.openremote.container.timer.TimerService;
import org.openremote.manager.asset.AssetStorageService;
import org.openremote.manager.rules.facade.NotificationsFacade;
import org.openremote.manager.rules.flow.*;
import org.openremote.manager.rules.flow.NodeExecutionRequestInfo;
import org.openremote.manager.rules.flow.NodeModel;
import org.openremote.manager.rules.flow.NodeTriggerFunction;
import org.openremote.manager.rules.flow.NodeTriggerParameters;
import org.openremote.model.rules.*;
import org.openremote.model.rules.flow.*;
import org.openremote.model.rules.flow.Node;
import org.openremote.model.rules.flow.NodeCollection;
import org.openremote.model.rules.flow.NodeSocket;
import org.openremote.model.rules.flow.NodeType;

import java.util.*;
import java.util.stream.Collectors;
import java.util.logging.Logger;

public class FlowRulesBuilder {
private AssetStorageService assetStorageService;
private Map<String, Long> triggerMap = new LinkedHashMap<>();
private List<NodeCollection> nodeCollections = new ArrayList<>();
private Assets assetsFacade;
private Users usersFacade;
private Notifications notificationFacade;
private HistoricDatapoints historicDatapointsFacade;
private PredictedDatapoints predictedDatapointsFacade;

private TimerService timerService;
protected final Logger LOG;
protected final AssetStorageService assetStorageService;
protected final Map<String, Long> triggerMap = new LinkedHashMap<>();
protected final List<NodeCollection> nodeCollections = new ArrayList<>();
protected final Assets assetsFacade;
protected final Users usersFacade;
protected final Notifications notificationFacade;
protected final HistoricDatapoints historicDatapointsFacade;
protected final PredictedDatapoints predictedDatapointsFacade;
protected final TimerService timerService;

public FlowRulesBuilder(
TimerService timerService,
AssetStorageService assetStorageService,
Assets assetsFacade,
Users usersFacade,
Notifications notificationFacade,
HistoricDatapoints historicDatapointsFacade,
PredictedDatapoints predictedDatapointsFacade) {
Logger logger,
TimerService timerService,
AssetStorageService assetStorageService,
Assets assetsFacade,
Users usersFacade,
Notifications notificationFacade,
HistoricDatapoints historicDatapointsFacade,
PredictedDatapoints predictedDatapointsFacade) {
this.timerService = timerService;
this.assetStorageService = assetStorageService;
this.assetsFacade = assetsFacade;
this.usersFacade = usersFacade;
this.notificationFacade = notificationFacade;
this.historicDatapointsFacade = historicDatapointsFacade;
this.predictedDatapointsFacade = predictedDatapointsFacade;
LOG = logger;
}

public void add(NodeCollection nodeCollection) {
@@ -52,11 +59,11 @@ public Rule[] build() {
for (Node node : collection.getNodes()) {
if (node.getType() != NodeType.OUTPUT) continue;
try {
RulesEngine.RULES_LOG.fine("Flow rule created");
LOG.fine("Flow rule created");
rules.add(createRule(collection.getName() + " - " + count, collection, node));
count++;
} catch (Exception e) {
RulesEngine.RULES_LOG.severe("Flow rule error: " + e.getMessage());
LOG.severe("Flow rule error: " + e.getMessage());
}
}
}
@@ -66,14 +73,9 @@ public Rule[] build() {
private Rule createRule(String name, NodeCollection collection, Node outputNode) throws Exception {
Object implementationResult = NodeModel.getImplementationFor(outputNode.getName()).execute(new NodeExecutionRequestInfo(collection, outputNode, null, null, assetsFacade, usersFacade, notificationFacade, historicDatapointsFacade, predictedDatapointsFacade));

if (implementationResult == null)
throw new NullPointerException(outputNode.getName() + " node returns null");

if (!(implementationResult instanceof RulesBuilder.Action))
if (!(implementationResult instanceof RulesBuilder.Action action))
throw new Exception(outputNode.getName() + " node does not return an action");

RulesBuilder.Action action = (RulesBuilder.Action) implementationResult;

RulesBuilder.Condition condition = facts -> {
List<Node> connectedTree = backtrackFrom(collection, outputNode);

@@ -89,16 +91,14 @@ private Rule createRule(String name, NodeCollection collection, Node outputNode)
name(name).
description(collection.getDescription()).
when(facts -> {
Object result;
try {
result = condition.evaluate((RulesFacts) facts);
} catch (Exception ex) {
throw new RuntimeException("Error evaluating condition of rule '" + name + "': " + ex.getMessage(), ex);
}
Object result = condition.evaluate((RulesFacts) facts);

if (result instanceof Boolean) {
return (boolean) result;
} else {
throw new IllegalArgumentException("Error evaluating condition of rule '" + name + "': result is not boolean but " + result);
String msg = "Error evaluating condition of rule, expected boolean but got " + (result != null ? result.getClass() : "null");
LOG.warning(msg);
throw new IllegalArgumentException(msg);
}
}).
then(facts -> {
@@ -113,7 +113,7 @@ private List<Node> backtrackFrom(NodeCollection collection, Node node) {
List<Node> children = new ArrayList<>();

for (NodeSocket s : node.getInputs()) {
children.addAll(Arrays.stream(collection.getConnections()).filter(c -> c.getTo().equals(s.getId())).map(c -> collection.getNodeById(collection.getSocketById(c.getFrom()).getNodeId())).collect(Collectors.toList()));
children.addAll(Arrays.stream(collection.getConnections()).filter(c -> c.getTo().equals(s.getId())).map(c -> collection.getNodeById(collection.getSocketById(c.getFrom()).getNodeId())).toList());
}

for (Node child : children) {
Original file line number Diff line number Diff line change
@@ -58,12 +58,12 @@
import java.util.function.Predicate;
import java.util.function.Supplier;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.stream.Collectors;
import java.util.stream.Stream;

import static org.openremote.manager.rules.AssetQueryPredicate.groupIsEmpty;
import static org.openremote.model.query.filter.LocationAttributePredicate.getLocationPredicates;
import static org.openremote.model.util.ValueUtil.LOG;
import static org.openremote.model.util.ValueUtil.distinctByKey;

public class JsonRulesBuilder extends RulesBuilder {
@@ -540,8 +540,9 @@ protected boolean updateMatches(LogicGroup<RuleCondition> ruleConditionGroup, Se
final protected Map<String, RuleState> ruleStateMap = new HashMap<>();
final protected JsonRule[] jsonRules;
final protected Ruleset jsonRuleset;
final protected Logger LOG;

public JsonRulesBuilder(Ruleset ruleset, TimerService timerService,
public JsonRulesBuilder(Logger logger, Ruleset ruleset, TimerService timerService,
AssetStorageService assetStorageService, ScheduledExecutorService executorService,
Assets assetsFacade, Users usersFacade, Notifications notificationsFacade, Webhooks webhooksFacade,
HistoricDatapoints historicDatapoints, PredictedDatapoints predictedDatapoints,
@@ -556,6 +557,7 @@ public JsonRulesBuilder(Ruleset ruleset, TimerService timerService,
this.historicDatapointsFacade= historicDatapoints;
this.predictedDatapointsFacade = predictedDatapoints;
this.scheduledActionConsumer = scheduledActionConsumer;
LOG = logger;

jsonRuleset = ruleset;
String rulesStr = ruleset.getRules();
@@ -1024,7 +1026,7 @@ protected RuleActionExecution buildRuleActionExecution(JsonRule rule, RuleAction
return null;
}

private static String buildTriggeredAssetInfo(boolean useUnmatched, RuleState ruleEvaluationResult, boolean isHtml, boolean isJson) {
private String buildTriggeredAssetInfo(boolean useUnmatched, RuleState ruleEvaluationResult, boolean isHtml, boolean isJson) {

Set<String> assetIds = useUnmatched ? ruleEvaluationResult.otherwiseMatchedAssetIds : ruleEvaluationResult.thenMatchedAssetIds;

@@ -1155,11 +1157,11 @@ protected static boolean targetIsNotAssets(RuleActionTarget target) {
}

protected void log(Level level, String message) {
RulesEngine.RULES_LOG.log(level, LOG_PREFIX + jsonRuleset.getName() + "': " + message);
LOG.log(level, LOG_PREFIX + jsonRuleset.getName() + "': " + message);
}

protected void log(Level level, String message, Throwable t) {
RulesEngine.RULES_LOG.log(level, LOG_PREFIX + jsonRuleset.getName() + "': " + message, t);
LOG.log(level, LOG_PREFIX + jsonRuleset.getName() + "': " + message, t);
}

protected static SunTimes.Parameters getSunCalculator(Ruleset ruleset, SunPositionTrigger sunPositionTrigger, TimerService timerService) throws IllegalStateException {
30 changes: 16 additions & 14 deletions manager/src/main/java/org/openremote/manager/rules/RulesEngine.java
Original file line number Diff line number Diff line change
@@ -43,6 +43,7 @@
import org.openremote.model.query.filter.GeofencePredicate;
import org.openremote.model.query.filter.LocationAttributePredicate;
import org.openremote.model.rules.*;
import org.openremote.model.syslog.SyslogCategory;

import java.util.*;
import java.util.concurrent.ConcurrentHashMap;
@@ -91,10 +92,7 @@ public Set<GeofencePredicate> getLocationPredicates() {
}
}

public static final Logger LOG = Logger.getLogger(RulesEngine.class.getName());

// Separate logger for execution of rules
public static final Logger RULES_LOG = Logger.getLogger("org.openremote.rules.Rules");
protected final Logger LOG;

// Separate logger for periodic stats printer
public static final Logger STATS_LOG = Logger.getLogger("org.openremote.rules.RulesEngineStats");
@@ -148,6 +146,10 @@ public RulesEngine(TimerService timerService,
this.assetStorageService = assetStorageService;
this.clientEventService = clientEventService;
this.id = id;

String ruleEngineCategory = id.scope.getSimpleName().replace("Ruleset", "Engine-") + id.getId().orElse("");
LOG = SyslogCategory.getLogger(SyslogCategory.RULES, RulesEngine.class.getName() + "." + ruleEngineCategory);

AssetsFacade<T> assetsFacade = new AssetsFacade<>(id, assetStorageService, attributeEvent -> {
try {
assetProcessingService.sendAttributeEvent(attributeEvent);
@@ -163,7 +165,7 @@ public RulesEngine(TimerService timerService,
this.predictedFacade = new PredictedFacade<>(id, assetPredictedDatapointService);
this.assetLocationPredicatesConsumer = assetLocationPredicatesConsumer;

this.facts = new RulesFacts(timerService, assetStorageService, assetsFacade, this, RULES_LOG);
this.facts = new RulesFacts(timerService, assetStorageService, assetsFacade, this, LOG);
engine = new DefaultRulesEngine(
// Skip any other rules after the first failed rule (exception thrown in condition or action)
new RulesEngineParameters(false, true, false, RulesEngineParameters.DEFAULT_RULE_PRIORITY_THRESHOLD)
@@ -317,7 +319,7 @@ public void start() {
return;
}

LOG.info("Starting: " + this);
LOG.info("Starting");
running = true;
trackLocationPredicates(true);

@@ -330,9 +332,9 @@ public void start() {
// Start a background stats printer if INFO level logging is enabled
if (STATS_LOG.isLoggable(Level.FINE) || STATS_LOG.isLoggable(Level.FINEST)) {
if (STATS_LOG.isLoggable(Level.FINEST)) {
LOG.info("On " + this + ", enabling periodic statistics output at FINEST level every 30 seconds on category: " + STATS_LOG.getName());
LOG.info("Enabling periodic statistics output at FINEST level every 30 seconds on category: " + STATS_LOG.getName());
} else {
LOG.info("On " + this + ", enabling periodic full memory dump at FINE level every 30 seconds on category: " + STATS_LOG.getName());
LOG.info("Enabling periodic full memory dump at FINE level every 30 seconds on category: " + STATS_LOG.getName());
}
statsTimer = executorService.scheduleAtFixedRate(this::printSessionStats, 3, 30, TimeUnit.SECONDS);
}
@@ -358,7 +360,7 @@ public void stop() {
return;
}
running = false;
LOG.info("Stopping: " + this);
LOG.info("Stopping");
if (fireTimer != null) {
fireTimer.cancel(true);
fireTimer = null;
@@ -419,7 +421,7 @@ protected synchronized void scheduleFire(boolean quickFire) {

long fireTimeMillis = quickFire ? rulesService.quickFireMillis : rulesService.tempFactExpirationMillis;

LOG.finest("Scheduling rules firing in " + fireTimeMillis + "ms on: " + this);
LOG.finest("Scheduling rules firing in " + fireTimeMillis + "ms");
fireTimer = executorService.schedule(
() -> {
synchronized (RulesEngine.this) {
@@ -457,9 +459,9 @@ protected void fireAllDeployments() {
executionTotalMillis = (timerService.getCurrentTimeMillis() - executionTotalMillis);

if (executionTotalMillis > 500) {
LOG.warning("Rules firing took " + executionTotalMillis + "ms on: " + this);
LOG.warning("Rules firing took " + executionTotalMillis + "ms");
} else {
LOG.fine("Rules firing took " + executionTotalMillis + "ms on: " + this);
LOG.fine("Rules firing took " + executionTotalMillis + "ms");
}
}

@@ -476,7 +478,7 @@ protected void doFire() {

// If full detail logging is enabled
// Log asset states and events before firing
facts.logFacts(RULES_LOG, Level.FINEST);
facts.logFacts(LOG, Level.FINEST);

// Reset facts for this firing (loop detection etc.)
facts.reset();
@@ -489,7 +491,7 @@ protected void doFire() {
LOG.fine("Rules deployment '" + deployment.getName() + "' skipped as status is: " + status);
}
} catch (Exception ex) {
LOG.log(Level.SEVERE, "On " + RulesEngine.this + ", error executing rules of: " + deployment, ex);
LOG.log(Level.SEVERE, "Error executing rules of: " + deployment, ex);

deployment.setStatus(ex instanceof RulesLoopException ? LOOP_ERROR : EXECUTION_ERROR);
deployment.setError(ex);
Original file line number Diff line number Diff line change
@@ -21,8 +21,8 @@

import org.openremote.model.rules.AssetRuleset;
import org.openremote.model.rules.GlobalRuleset;
import org.openremote.model.rules.Ruleset;
import org.openremote.model.rules.RealmRuleset;
import org.openremote.model.rules.Ruleset;

import java.util.Objects;
import java.util.Optional;
@@ -73,6 +73,10 @@ public Optional<String> getAssetId() {
return Optional.ofNullable(assetId);
}

public Optional<String> getId() {
return scope == RealmRuleset.class ? getRealm() : scope == AssetRuleset.class ? getAssetId() : Optional.empty();
}

@Override
public boolean equals(Object o) {
if (this == o) return true;
Loading
Oops, something went wrong.

0 comments on commit 2699cbc

Please sign in to comment.