Skip to content

Commit

Permalink
Avoid extra logging on system configuration change
Browse files Browse the repository at this point in the history 
New logging configuration, caching configuration, and full-text
search configurations are applied only if there was a real change
in the respective data.

This eliminates useless log messages and (in some cases) useless work,
because e.g. logging config update application is not free.

Unrelated changes:
- Fixed op. result handling in LoggingConfigurationManager.
- Fixed modifying immutable data in ProfilingConfigurationManager.
- Make methods that update the configuration synchronized.

This resolves MID-4638.
  • Loading branch information
@mederly
mederly committed Mar 24, 2022
1 parent 72774bb commit d095693
Show file tree
Hide file tree
Showing 5 changed files with 111 additions and 53 deletions.
95 changes: 59 additions & 36 deletions infra/common/src/main/java/com/evolveum/midpoint/common/LoggingConfigurationManager.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,8 +18,12 @@
import ch.qos.logback.classic.joran.JoranConfigurator;
import ch.qos.logback.core.joran.spi.JoranException;
import ch.qos.logback.core.util.StatusPrinter;

import com.evolveum.midpoint.prism.util.PrismUtil;

import org.apache.commons.configuration2.Configuration;
import org.apache.commons.lang3.StringUtils;
import org.jetbrains.annotations.Nullable;
import org.slf4j.bridge.SLF4JBridgeHandler;

import com.evolveum.midpoint.common.configuration.api.MidpointConfiguration;
Expand Down Expand Up @@ -48,32 +52,54 @@ public class LoggingConfigurationManager {
private static final String TRACING_APPENDER_CLASS_NAME = TracingAppender.class.getName();
private static final LoggingLevelType DEFAULT_PROFILING_LEVEL = LoggingLevelType.INFO;

private static String currentlyUsedVersion = null;
private static final String OP_CONFIGURE = LoggingConfigurationManager.class.getName() + ".configure";

public static void configure(LoggingConfigurationType config, String version,
MidpointConfiguration midpointConfiguration, OperationResult result) throws SchemaException {
/** Determines whether we apply the new configuration. */
private static LoggingConfigurationType currentlyUsedConfiguration;

OperationResult res = result.createSubresult(LoggingConfigurationManager.class.getName() + ".configure");
public synchronized static void configure(
@Nullable LoggingConfigurationType updatedConfiguration,
String updatedVersion,
MidpointConfiguration midpointConfiguration,
OperationResult parentResult) throws SchemaException {

if (InternalsConfig.isAvoidLoggingChange()) {
LOGGER.info("IGNORING change of logging configuration (current config version: {}, new version {}) because avoidLoggingChange=true", currentlyUsedVersion, version);
res.recordNotApplicableIfUnknown();
return;
}
OperationResult result = parentResult.createSubresult(OP_CONFIGURE);
try {

if (java.util.Objects.equals(currentlyUsedVersion, version)) {
LOGGER.debug("Skipped logging configuration because the same version {}"
+ " is already configured", version);
res.recordNotApplicableIfUnknown();
return;
}
if (InternalsConfig.isAvoidLoggingChange()) {
LOGGER.info("IGNORING change of logging configuration (version {}) because avoidLoggingChange=true",
updatedVersion);
result.recordNotApplicableIfUnknown();
return;
}

if (currentlyUsedVersion != null) {
LOGGER.info("Applying logging configuration (currently applied version: {}, new version: {})", currentlyUsedVersion, version);
} else {
LOGGER.info("Applying logging configuration (version {})", version);
if (PrismUtil.realValueEquals(currentlyUsedConfiguration, updatedConfiguration)) {
LOGGER.debug("Skipped logging configuration update (version {}) because the same configuration is already"
+ " applied", updatedVersion);
result.recordNotApplicableIfUnknown();
return;
}

LOGGER.info("Applying logging configuration (system configuration version {})", updatedVersion);

applyConfiguration(updatedConfiguration, midpointConfiguration, result);

currentlyUsedConfiguration = updatedConfiguration != null && !updatedConfiguration.isImmutable() ?
updatedConfiguration.clone() : updatedConfiguration;

} catch (Throwable t) {
result.recordFatalError(t);
throw t;
} finally {
result.close();
}
currentlyUsedVersion = version;
}

private static void applyConfiguration(
LoggingConfigurationType updatedConfiguration,
MidpointConfiguration midpointConfiguration,
OperationResult result)
throws SchemaException {

// JUL Bridge initialization was here. (SLF4JBridgeHandler)
// But it was moved to a later phase as suggested by http://jira.qos.ch/browse/LOGBACK-740
Expand All @@ -82,32 +108,29 @@ public static void configure(LoggingConfigurationType config, String version,
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();

//Get current log configuration
// Get current log configuration
LoggerContext lc = (LoggerContext) TraceManager.getILoggerFactory();

//Prepare configurator in current context
// Prepare configurator in current context
JoranConfigurator configurator = new JoranConfigurator();
configurator.setContext(lc);

//Generate configuration file as string
String configXml = prepareConfiguration(config, midpointConfiguration);
// Generate configuration file as string
String configXml = prepareConfiguration(updatedConfiguration, midpointConfiguration);

if (LOGGER.isTraceEnabled()) {
LOGGER.trace("New logging configuration:");
LOGGER.trace(configXml);
}
LOGGER.trace("New logging configuration:\n{}", configXml);

InputStream cis = new ByteArrayInputStream(configXml.getBytes());
LOGGER.debug("Resetting current logging configuration");
lc.getStatusManager().clear();
//Set all loggers to error
// Set all loggers to error
for (Logger l : lc.getLoggerList()) {
LOGGER.trace("Disable logger: {}", l);
l.setLevel(Level.ERROR);
}
// Reset configuration
lc.reset();
//Switch to new logging configuration
// Switch to new logging configuration
lc.setName("MidPoint");
try {
configurator.doConfigure(cis);
Expand All @@ -118,25 +141,25 @@ public static void configure(LoggingConfigurationType config, String version,
result.createSubresult("Applying logging configuration.").recordFatalError(e.getMessage(), e);
}

//Get messages if error occurred;
// Get messages if error occurred;
ByteArrayOutputStream baos = new ByteArrayOutputStream();
StatusPrinter.setPrintStream(new PrintStream(baos));
StatusPrinter.print(lc);

String internalLog = baos.toString(StandardCharsets.UTF_8);

if (!StringUtils.isEmpty(internalLog)) {
//Parse internal log
res.recordSuccess();
// Parse internal log
result.recordSuccess();
for (String internalLogLine : internalLog.split("\n")) {
if (internalLogLine.contains("|-ERROR")) {
res.recordPartialError(internalLogLine);
result.recordPartialError(internalLogLine);
}
res.appendDetail(internalLogLine);
result.appendDetail(internalLogLine);
}
LOGGER.trace("LogBack internal log:\n{}", internalLog);
} else {
res.recordSuccess();
result.recordSuccess();
}

// Initialize JUL bridge
Expand Down
11 changes: 8 additions & 3 deletions infra/common/src/main/java/com/evolveum/midpoint/common/ProfilingConfigurationManager.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -28,9 +28,11 @@ public class ProfilingConfigurationManager {
private static final String APPENDER_IDM_PROFILE = "MIDPOINT_PROFILE_LOG";

/**
* In this method, we perform the check of systemConfiguration object, searching for any data
* related to profilingConfiguration
* */
* In this method, we perform the check of systemConfiguration object, searching for any data
* related to profilingConfiguration.
*
* @return The logging configuration, updated by profiling-related loggers (if profiling is enabled).
*/
public static LoggingConfigurationType checkSystemProfilingConfiguration(PrismObject<SystemConfigurationType> systemConfigurationPrism){
if (systemConfigurationPrism == null) {
return null;
Expand All @@ -53,6 +55,9 @@ private static LoggingConfigurationType applyProfilingConfiguration(PrismObject<
LoggingConfigurationType loggingConfig = systemConfig.getLogging();

if (loggingConfig != null) {
if (loggingConfig.isImmutable()) {
loggingConfig = loggingConfig.clone();
}
if (checkXsdBooleanValue(profilingConfig.isRequestFilter())) {
ClassLoggerConfigurationType requestFilterLogger = new ClassLoggerConfigurationType();
requestFilterLogger.setPackage(REQUEST_FILTER_LOGGER_CLASS_NAME);
Expand Down
42 changes: 30 additions & 12 deletions infra/schema/src/main/java/com/evolveum/midpoint/schema/cache/CacheConfigurationManager.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
package com.evolveum.midpoint.schema.cache;

import com.evolveum.midpoint.prism.PrismContext;
import com.evolveum.midpoint.prism.util.PrismUtil;
import com.evolveum.midpoint.schema.constants.ObjectTypes;
import com.evolveum.midpoint.util.DebugDumpable;
import com.evolveum.midpoint.util.DebugUtil;
Expand Down Expand Up @@ -54,7 +55,7 @@ public class CacheConfigurationManager {
private CachingConfigurationType currentGlobalConfiguration;

private boolean wrongConfiguration;
private Map<CacheType, CacheConfiguration> compiledGlobalConfigurations; // not null if !wrongConfiguration
private Map<CacheType, CacheConfiguration> compiledGlobalConfigurations; // not null if !wrongConfiguration

private final ThreadLocal<ThreadLocalConfiguration> threadLocalConfiguration = new ThreadLocal<>();

Expand All @@ -75,18 +76,31 @@ public void initialize() {
}
}

public void applyCachingConfiguration(SystemConfigurationType configuration) {
InternalsConfigurationType internals = configuration != null ? configuration.getInternals() : null;
currentGlobalConfiguration = internals != null ? internals.getCaching() : null;
public synchronized void applyCachingConfiguration(SystemConfigurationType systemConfiguration) {
InternalsConfigurationType internals = systemConfiguration != null ? systemConfiguration.getInternals() : null;
CachingConfigurationType configurationToApply = internals != null ? internals.getCaching() : null;
if (PrismUtil.realValueEquals(currentGlobalConfiguration, configurationToApply)) {
LOGGER.trace("Caching configuration was not changed, skipping the update");
return;
}

if (validateSystemConfiguration()) {
LOGGER.info("Applied caching configuration: {} profiles",
currentGlobalConfiguration != null ? currentGlobalConfiguration.getProfile().size() : 0);
compiledGlobalConfigurations = compileConfigurations(currentGlobalConfiguration, emptySet());
wrongConfiguration = false;
} else {
compiledGlobalConfigurations = null;
currentGlobalConfiguration = configurationToApply;
try {
if (validateSystemConfiguration()) {
LOGGER.info("Applying caching configuration: {} profile(s)",
currentGlobalConfiguration != null ? currentGlobalConfiguration.getProfile().size() : 0);
compiledGlobalConfigurations = compileConfigurations(currentGlobalConfiguration, emptySet());
wrongConfiguration = false;
} else {
compiledGlobalConfigurations = null;
wrongConfiguration = true;
}
} catch (Throwable t) {
// Couldn't we do the update without setting global config before the application is done?
// We wouldn't need clearing that information in case of error.
currentGlobalConfiguration = null;
wrongConfiguration = true;
throw t;
}
}

Expand Down Expand Up @@ -205,7 +219,7 @@ private Map<CacheType, CacheConfiguration> compileConfigurations(@Nullable Cachi
for (CachingProfileType profile : relevantProfiles) {
addProfile(rv, profile);
}
if (configuration != null && Boolean.TRUE.equals(configuration.isTraceConfiguration())) {
if (shouldTrace(configuration)) {
LOGGER.info("Compiled configurations (profiles = {}):", profiles);
for (Map.Entry<CacheType, CacheConfiguration> entry : rv.entrySet()) {
LOGGER.info(" {}:\n{}", entry.getKey(), entry.getValue().debugDump(2));
Expand All @@ -220,6 +234,10 @@ private Map<CacheType, CacheConfiguration> compileConfigurations(@Nullable Cachi
}
}

private boolean shouldTrace(@Nullable CachingConfigurationType configuration) {
return configuration != null && Boolean.TRUE.equals(configuration.isTraceConfiguration());
}

private void addProfile(Map<CacheType, CacheConfiguration> aggregate, CachingProfileType profile) throws SchemaException {
if (profile.getLocalRepoCache() != null) {
if (profile.getLocalRepoObjectCache() != null || profile.getLocalRepoVersionCache() != null || profile.getLocalRepoQueryCache() != null) {
Expand Down
8 changes: 7 additions & 1 deletion repo/repo-sqale/src/main/java/com/evolveum/midpoint/repo/sqale/SqaleRepositoryService.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@
import java.util.stream.Collectors;
import javax.xml.namespace.QName;

import com.evolveum.midpoint.prism.util.PrismUtil;

import com.google.common.base.Strings;
import com.google.common.collect.ObjectArrays;
import com.querydsl.core.Tuple;
Expand Down Expand Up @@ -1821,7 +1823,11 @@ public <O extends ObjectType> boolean selectorMatches(
}

@Override
public void applyFullTextSearchConfiguration(FullTextSearchConfigurationType fullTextSearch) {
public synchronized void applyFullTextSearchConfiguration(FullTextSearchConfigurationType fullTextSearch) {
if (PrismUtil.realValueEquals(fullTextSearchConfiguration, fullTextSearch)) {
logger.trace("Ignoring full text search configuration update => the real value has not changed");
return;
}
logger.info("Applying full text search configuration ({} entries)",
fullTextSearch != null ? fullTextSearch.getIndexed().size() : 0);
fullTextSearchConfiguration = fullTextSearch;
Expand Down
8 changes: 7 additions & 1 deletion .../repo-sql-impl/src/main/java/com/evolveum/midpoint/repo/sql/SqlRepositoryServiceImpl.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@
import javax.annotation.PreDestroy;
import javax.xml.namespace.QName;

import com.evolveum.midpoint.prism.util.PrismUtil;

import org.apache.commons.lang3.Validate;
import org.hibernate.Session;
import org.hibernate.SessionFactory;
Expand Down Expand Up @@ -1275,7 +1277,11 @@ public <O extends ObjectType> boolean isAncestor(
}

@Override
public void applyFullTextSearchConfiguration(FullTextSearchConfigurationType fullTextSearch) {
public synchronized void applyFullTextSearchConfiguration(FullTextSearchConfigurationType fullTextSearch) {
if (PrismUtil.realValueEquals(fullTextSearchConfiguration, fullTextSearch)) {
LOGGER.trace("Ignoring full text search configuration update => the real value has not changed");
return;
}
LOGGER.info("Applying full text search configuration ({} entries)",
fullTextSearch != null ? fullTextSearch.getIndexed().size() : 0);
fullTextSearchConfiguration = fullTextSearch;
Expand Down

0 comments on commit d095693

Please sign in to comment.