diff --git a/api/build.gradle b/api/build.gradle index 04c7fa4f960..959d150a520 100644 --- a/api/build.gradle +++ b/api/build.gradle @@ -61,11 +61,11 @@ List caching = [ "net.sf.ehcache:ehcache-core:${ehcacheCoreVersion}" ] -// TODO : log4j - change it to use log4j2version +// TODO : log4j - change it to use log4j2version before final merge List logging = [ "org.apache.logging.log4j:log4j-core:2.13.3", "org.apache.logging.log4j:log4j-api:2.13.3", - "org.apache.logging.log4j:log4j-1.2-api:2.13.3" +// "org.apache.logging.log4j:log4j-1.2-api:2.13.3" ] List r = [ diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index 406a8c64ac5..f4e965ab231 100644 --- a/api/src/org/labkey/api/data/ConnectionWrapper.java +++ b/api/src/org/labkey/api/data/ConnectionWrapper.java @@ -22,6 +22,7 @@ import org.apache.logging.log4j.core.config.LoggerConfig; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.labkey.api.util.LoggerWriter; import org.labkey.api.data.DbScope.ConnectionType; import org.labkey.api.data.dialect.SqlDialect; import org.labkey.api.data.dialect.StatementWrapper; @@ -30,6 +31,7 @@ import org.labkey.api.util.DateUtil; import org.labkey.api.util.MemTracker; import org.labkey.api.util.Pair; +import org.labkey.api.util.SimpleLoggerWriter; import org.labkey.api.view.ViewServlet; import java.lang.reflect.Method; @@ -152,7 +154,7 @@ public static boolean dumpOpenConnections() return dumpOpenConnections(_logDefault); } - public static boolean dumpOpenConnections(@NotNull Logger log) + public static boolean dumpOpenConnections(@NotNull LoggerWriter logWriter) { synchronized (_openConnections) { @@ -160,19 +162,31 @@ public static boolean dumpOpenConnections(@NotNull Logger log) { String thread = p.first.getName(); Throwable t = p.second; - log.debug("Connection opened on thread: " + thread, t); + logWriter.debug("Connection opened on thread: " + thread, t); } } return true; } + public static boolean dumpOpenConnections(@NotNull Logger log) + { + dumpOpenConnections(new SimpleLoggerWriter(log)); + + return true; + } + public static boolean dumpLeaksForThread(Thread t) { return dumpLeaksForThread(t, _logDefault); } public static boolean dumpLeaksForThread(Thread t, Logger log) + { + return dumpOpenConnections(new SimpleLoggerWriter(log)); + } + + public static boolean dumpLeaksForThread(Thread t, LoggerWriter log) { boolean leaks = false; synchronized(_openConnections) diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 4038de79e93..d4cc38beb57 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -41,7 +41,9 @@ import org.labkey.api.test.TestWhen; import org.labkey.api.util.ConfigurationException; import org.labkey.api.util.GUID; +import org.labkey.api.util.LoggerWriter; import org.labkey.api.util.MemTracker; +import org.labkey.api.util.SimpleLoggerWriter; import org.labkey.api.util.TestContext; import org.labkey.api.util.UnexpectedException; import org.labkey.data.xml.TablesDocument; @@ -978,7 +980,7 @@ public void logCurrentConnectionState() logCurrentConnectionState(LOG); } - public void logCurrentConnectionState(@NotNull Logger log) + public void logCurrentConnectionState(LoggerWriter log) { synchronized (_transaction) { @@ -1015,6 +1017,12 @@ public void logCurrentConnectionState(@NotNull Logger log) } } + public void logCurrentConnectionState(@NotNull Logger log) + { + logCurrentConnectionState(new SimpleLoggerWriter(log)); + } + + private static final int spidUnknown = -1; protected ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logger log) throws SQLException diff --git a/api/src/org/labkey/api/pipeline/PipelineJob.java b/api/src/org/labkey/api/pipeline/PipelineJob.java index 6c4d0ad206e..ca640167ab0 100644 --- a/api/src/org/labkey/api/pipeline/PipelineJob.java +++ b/api/src/org/labkey/api/pipeline/PipelineJob.java @@ -25,7 +25,10 @@ import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Layout; import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.config.AppenderRef; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.LoggerConfig; import org.apache.logging.log4j.core.layout.PatternLayout; @@ -796,6 +799,8 @@ public void runActiveTask() throws IOException, PipelineJobException { getLogger().info((success ? "Successfully completed" : "Failed to complete") + " task '" + factory.getId() + "'"); logStartStopInfo((success ? "Successfully completed" : "Failed to complete") + " task '" + factory.getId() + "' for job '" + toString() + "' with log file " + getLogFile()); + // remove temporary logger created for the job + removeLogger(); try { if (workDirectory != null) @@ -1351,140 +1356,6 @@ else if (count == logLineInterval) } - ///////////////////////////////////////////////////////////////////////// - // Logging - - /** - * Log4J Logger subclass to allow us to create loggers that are not cached - * in the Log4J repository for the life of the webapp. This logger also - * logs to the weblog for the PipelineJob class, allowing administrators - * to collect whatever level of logging they want from PipelineJobs. - */ - private static class OutputLogger extends org.apache.logging.log4j.core.Logger - { - private final PipelineJob _job; - private boolean _isSettingStatus; - - // Required for xstream serialization on Java 7 - @SuppressWarnings({"UnusedDeclaration"}) - private OutputLogger() - { - //noinspection NullableProblems - this(null, ""); - } - - protected OutputLogger(PipelineJob job, String name) - { - super((LoggerContext) LogManager.getContext(), name, LogManager.getLogger(name).getMessageFactory()); - - _job = job; - } - - @Override - public void debug(Object message) - { - debug(message, null); - } - - @Override - public void debug(Object message, @Nullable Throwable t) - { - _job.getClassLogger().debug(getSystemLogMessage(message), t); - super.debug(message, t); - } - - @Override - public void info(Object message) - { - info(message, null); - } - - @Override - public void info(Object message, @Nullable Throwable t) - { - _job.getClassLogger().info(getSystemLogMessage(message), t); - super.info(message, t); - } - - @Override - public void warn(Object message) - { - warn(message, null); - } - - @Override - public void warn(Object message, @Nullable Throwable t) - { - _job.getClassLogger().warn(getSystemLogMessage(message), t); - super.warn(message, t); - } - - @Override - public void error(Object message) - { - error(message, null); - } - - @Override - public void error(Object message, @Nullable Throwable t) - { - _job.getClassLogger().error(getSystemLogMessage(message), t); - super.error(message, t); - setErrorStatus(message); - } - - @Override - public void fatal(Object message) - { - fatal(message, null); - } - - @Override - public void fatal(Object message, Throwable t) - { - _job.getClassLogger().fatal(getSystemLogMessage(message), t); - super.fatal(message, t); - setErrorStatus(message); - } - - private String getSystemLogMessage(Object message) - { - StringBuilder sb = new StringBuilder(); - sb.append("(from pipeline job log file "); - sb.append(_job.getLogFile().getPath()); - if (message != null) - { - sb.append(": "); - String stringMessage = message.toString(); - // Limit the maximum line length - final int maxLength = 10000; - if (stringMessage.length() > maxLength) - { - stringMessage = stringMessage.substring(0, maxLength) + "..."; - } - sb.append(stringMessage); - } - sb.append(")"); - return sb.toString(); - } - - public void setErrorStatus(Object message) - { - if (_isSettingStatus) - return; - - _isSettingStatus = true; - try - { - _job.setStatus(TaskStatus.error, message == null ? "ERROR" : message.toString()); - } - finally - { - _isSettingStatus = false; - } - } - } - public String getLogLevel() { return _loggerLevel; @@ -1514,19 +1385,48 @@ public synchronized Logger getLogger() File logFile = null != _logFile ? _logFile : new File(_logFilePathName); // Create appending logger. - _logger = new OutputLogger(this, PipelineJob.class.getSimpleName() + ".Logger." + _logFilePathName); - LoggerContext loggerContext = (LoggerContext) LogManager.getContext(true); - Configuration configuration = loggerContext.getConfiguration(); - LoggerConfig loggerConfig = configuration.getLoggerConfig(_logger.getName()); - loggerConfig.getAppenders().forEach((key, value) -> loggerConfig.removeAppender(value.getName())); - - SafeFileAppender appender = SafeFileAppender.createAppender("SafeFile", false, PatternLayout.newBuilder().withPattern("%d{DATE} %-5p: %m%n").build(), null, logFile); - loggerConfig.addAppender(appender, Level.toLevel(_loggerLevel), null); + final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); + final Configuration config = ctx.getConfiguration(); + + // Programmatically adding appender and logger config to log4j2 config + String appenderName = "SafeFile"; + Layout layout = PatternLayout.newBuilder().withPattern("%d{DATE} %-5p: %m%n").build(); + Appender appender = SafeFileAppender.createAppender(appenderName, false, layout, null, logFile, this); + appender.start(); + config.addAppender(appender); + + AppenderRef ref = AppenderRef.createAppenderRef(appenderName, null, null); + AppenderRef[] refs = new AppenderRef[] {ref}; + String loggerName = PipelineJob.class.getSimpleName() + ".Logger." + _logFilePathName; + LoggerConfig loggerConfig = LoggerConfig.createLogger(false, Level.toLevel(_loggerLevel), loggerName, "true", refs, null, config, null ); + loggerConfig.addAppender(appender, null, null); + config.addLogger(loggerName, loggerConfig); + ctx.updateLoggers(); + + // Now that the log4j2 config contains the logger, access the logger through LogManager + _logger = LogManager.getLogger(loggerName); } return _logger; } + /** + * This method removes the logger created for this pipeline job so that it does not live + * in the Log4J2 repository for the life of the webapp. + * */ + public synchronized void removeLogger() + { + if (_logger != null) + { + final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); + final Configuration config = ctx.getConfiguration(); + String loggerName = PipelineJob.class.getSimpleName() + ".Logger." + _logFilePathName; + config.removeLogger(loggerName); + ctx.updateLoggers(); + _logger = null; + } + } + public void error(String message) { error(message, null); diff --git a/api/src/org/labkey/api/security/ConfigurationSettings.java b/api/src/org/labkey/api/security/ConfigurationSettings.java index c8910803ec3..2c14db58c06 100644 --- a/api/src/org/labkey/api/security/ConfigurationSettings.java +++ b/api/src/org/labkey/api/security/ConfigurationSettings.java @@ -1,7 +1,8 @@ package org.labkey.api.security; import org.apache.commons.codec.binary.Base64; -import org.apache.log4j.Logger; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.json.JSONObject; import org.labkey.api.data.AES; import org.labkey.api.settings.AppProps; @@ -10,7 +11,7 @@ public class ConfigurationSettings { - private static final Logger LOG = Logger.getLogger(ConfigurationSettings.class); + private static final Logger LOG = LogManager.getLogger(ConfigurationSettings.class); private final Map _standardSettings; private final Map _properties; diff --git a/api/src/org/labkey/api/security/ValidEmail.java b/api/src/org/labkey/api/security/ValidEmail.java index 355b1313a57..95eacd562c2 100644 --- a/api/src/org/labkey/api/security/ValidEmail.java +++ b/api/src/org/labkey/api/security/ValidEmail.java @@ -17,7 +17,8 @@ package org.labkey.api.security; import org.apache.commons.lang3.StringUtils; -import org.apache.log4j.Logger; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.junit.Assert; import org.junit.Test; import org.labkey.api.data.ColumnInfo; @@ -45,7 +46,7 @@ */ public class ValidEmail { - private static final Logger LOG = Logger.getLogger(ValidEmail.class); + private static final Logger LOG = LogManager.getLogger(ValidEmail.class); private final InternetAddress _internetAddress; diff --git a/api/src/org/labkey/api/util/DebugInfoDumper.java b/api/src/org/labkey/api/util/DebugInfoDumper.java index f9aaeb8497c..d8bf0b645d5 100644 --- a/api/src/org/labkey/api/util/DebugInfoDumper.java +++ b/api/src/org/labkey/api/util/DebugInfoDumper.java @@ -230,22 +230,22 @@ public static File dumpHeap() throws Exception } /** - * Writes the current set of thread stacks once to the supplied logger. - */ - public static synchronized void dumpThreads(Logger log) + * Writes the thread dump into threads.txt + * */ + public static synchronized void dumpThreads(LoggerWriter logWriter) { - log.debug("*********************************************"); - log.debug("Starting thread dump - " + LocalDateTime.now().toString()); + logWriter.debug("*********************************************"); + logWriter.debug("Starting thread dump - " + LocalDateTime.now().toString()); long used = ManagementFactory.getMemoryMXBean().getHeapMemoryUsage().getUsed(); long max = ManagementFactory.getMemoryMXBean().getHeapMemoryUsage().getMax(); - log.debug("Heap usage at " + DecimalFormat.getPercentInstance().format(((double)used / (double)max)) + " - " + + logWriter.debug("Heap usage at " + DecimalFormat.getPercentInstance().format(((double)used / (double)max)) + " - " + FileUtils.byteCountToDisplaySize(used) + " from a max of " + FileUtils.byteCountToDisplaySize(max) + " (" + DecimalFormat.getInstance().format(used) + " / " + DecimalFormat.getInstance().format(max) + " bytes)"); - log.debug("*********************************************"); + logWriter.debug("*********************************************"); Map threads = Thread.getAllStackTraces(); for (Map.Entry threadEntry : threads.entrySet()) { - log.debug(""); + logWriter.debug(""); Thread thread = threadEntry.getKey(); StringBuilder threadInfo = new StringBuilder(thread.getName()); threadInfo.append(" ("); @@ -258,39 +258,47 @@ public static synchronized void dumpThreads(Logger log) threadInfo.append(", Database Connection SPIDs = "); threadInfo.append(spids); } - log.debug(threadInfo); + logWriter.debug(threadInfo.toString()); String uri = ViewServlet.getRequestURL(thread); if (null != uri) - log.debug(uri); + logWriter.debug(uri); for (StackTraceElement stackTraceElement : threadEntry.getValue()) { - log.debug("\t" + stackTraceElement.toString()); + logWriter.debug("\t" + stackTraceElement.toString()); } if (ConnectionWrapper.getProbableLeakCount() > 0) { - ConnectionWrapper.dumpLeaksForThread(thread, log); + ConnectionWrapper.dumpLeaksForThread(thread, logWriter); } } - log.debug("*********************************************"); - log.debug("Completed thread dump"); - log.debug("*********************************************"); + logWriter.debug("*********************************************"); + logWriter.debug("Completed thread dump"); + logWriter.debug("*********************************************"); for (DbScope dbScope : DbScope.getDbScopes()) { - dbScope.logCurrentConnectionState(log); + dbScope.logCurrentConnectionState(logWriter); } if (ConnectionWrapper.getActiveConnectionCount() > 0) { - log.debug("*********************************************"); - log.debug("Start dump of all open connections"); - log.debug("*********************************************"); - ConnectionWrapper.dumpOpenConnections(log); - log.debug("*********************************************"); - log.debug("Completed dump of all open connections"); - log.debug("*********************************************"); + logWriter.debug("*********************************************"); + logWriter.debug("Start dump of all open connections"); + logWriter.debug("*********************************************"); + ConnectionWrapper.dumpOpenConnections(logWriter); + logWriter.debug("*********************************************"); + logWriter.debug("Completed dump of all open connections"); + logWriter.debug("*********************************************"); } } + + /** + * Writes the current set of thread stacks once to the supplied logger. + */ + public static synchronized void dumpThreads(Logger log) + { + dumpThreads(new SimpleLoggerWriter(log)); + } } diff --git a/api/src/org/labkey/api/util/FileLoggerWriter.java b/api/src/org/labkey/api/util/FileLoggerWriter.java new file mode 100644 index 00000000000..1bc8bce4cef --- /dev/null +++ b/api/src/org/labkey/api/util/FileLoggerWriter.java @@ -0,0 +1,151 @@ +package org.labkey.api.util; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.jetbrains.annotations.Nullable; + +import java.io.BufferedWriter; +import java.io.File; +import java.io.FileWriter; +import java.io.IOException; + +/** + * This loggerWriter will log the contents in a file. + * */ +public class FileLoggerWriter implements LoggerWriter, AutoCloseable +{ + private final String LINE_SEP = System.getProperty("line.separator"); + private static Logger LOG = LogManager.getLogger(FileLoggerWriter.class); + + private File _file; + private BufferedWriter _writer; + + public FileLoggerWriter(File file) + { + _file = file; + // Make sure that we try to mount the drive (if needed) before using the file + NetworkDrive.exists(_file); + try + { + _writer = new BufferedWriter(new FileWriter(_file, true)); + } + catch (IOException e) + { + LOG.error("Failed opening the file - " + _file.getName() , e); + } + + } + + @Override + public void close() + { + try + { + _writer.close(); + } + catch (IOException e) + { + LOG.error("Unable to close the file - " + _file.getName(), e); + } + } + + private boolean isFilePresent() + { + return _file != null; + } + + @Override + public void write(String message, @Nullable Throwable t) + { + if (isFilePresent()) + { + try + { + _writer.write(message); + _writer.write(LINE_SEP); + + if (null != t) + { + StackTraceElement[] stackTraceElements = t.getStackTrace(); + if (stackTraceElements != null) + { + for (StackTraceElement stackTraceElement : stackTraceElements) + { + _writer.write(stackTraceElement.toString()); + _writer.write(LINE_SEP); + } + } + } + } + catch (IOException e) + { + LOG.error("Failed appending to file - " + _file.getName(), e); + } + } + else + { + LOG.error("File not provided to write logs."); + } + + } + + @Override + public void debug(String message) + { + write(message, null); + } + + @Override + public void debug(String message, Throwable t) + { + write(message, t); + } + + @Override + public void error(String message) + { + write(message, null); + } + + @Override + public void error(String message, Throwable t) + { + write(message, t); + } + + @Override + public void info(String message) + { + write(message, null); + } + + @Override + public void info(String message, Throwable t) + { + write(message, t); + } + + @Override + public void fatal(String message) + { + write(message, null); + } + + @Override + public void fatal(String message, Throwable t) + { + write(message, t); + } + + @Override + public void trace(String message) + { + write(message, null); + } + + @Override + public void trace(String message, Throwable t) + { + write(message, t); + } +} diff --git a/api/src/org/labkey/api/util/LoggerWriter.java b/api/src/org/labkey/api/util/LoggerWriter.java new file mode 100644 index 00000000000..4f0f776fd56 --- /dev/null +++ b/api/src/org/labkey/api/util/LoggerWriter.java @@ -0,0 +1,36 @@ +package org.labkey.api.util; + +import org.jetbrains.annotations.Nullable; + +/** + * This is the helper class to provide a custom logger writer which can be + * used to route log messages to a different location than the logger. ex - to a file. + * + * User : ankurj + * Date : Jul 23, 2020 + * */ + +public interface LoggerWriter +{ + void write(String message, @Nullable Throwable t); + + void debug(String message); + + void debug(String message, Throwable t); + + void error(String message); + + void error(String message, Throwable t); + + void info(String message); + + void info(String message, Throwable t); + + void fatal(String message); + + void fatal(String message, Throwable t); + + void trace(String message); + + void trace(String message, Throwable t); +} diff --git a/api/src/org/labkey/api/util/MXBeanAppender.java b/api/src/org/labkey/api/util/MXBeanAppender.java deleted file mode 100644 index c0602069f0b..00000000000 --- a/api/src/org/labkey/api/util/MXBeanAppender.java +++ /dev/null @@ -1,138 +0,0 @@ -/* - * Copyright (c) 2012-2013 LabKey Corporation - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.labkey.api.util; - -import org.apache.logging.log4j.Level; -import org.apache.logging.log4j.core.Filter; -import org.apache.logging.log4j.core.Layout; -import org.apache.logging.log4j.core.LogEvent; -import org.apache.logging.log4j.core.appender.AbstractAppender; -import org.apache.logging.log4j.core.config.Property; -import org.apache.logging.log4j.core.config.plugins.Plugin; -import org.labkey.api.mbean.ErrorsMXBean; -import org.labkey.api.mbean.LabKeyManagement; - -import javax.management.DynamicMBean; -import javax.management.StandardMBean; -import java.io.Serializable; -import java.util.Date; -import java.util.LinkedList; -import java.util.concurrent.TimeUnit; - -/** - * User: matthewb - * Date: 2012-02-28 - * Time: 4:10 PM - */ -@Plugin(name = "SessionAppender", category = "Core", elementType = "appender", printObject = true) -public class MXBeanAppender extends AbstractAppender implements ErrorsMXBean -{ - public MXBeanAppender(String name, Filter filter, Layout layout, boolean ignoreExceptions, Property[] properties) - { - super(name, filter, layout, ignoreExceptions, properties); - DynamicMBean mbean = new StandardMBean(this, ErrorsMXBean.class, true); - LabKeyManagement.register(mbean, "Errors", "recent"); - } - - private static class _Error implements Error - { - final LogEvent _event; - _Error(LogEvent e) - { - _event = e; - } - - @Override - public Date getTime() - { - return new Date(_event.getTimeMillis()); - } - - @Override - public String getMessage() - { - return String.valueOf(_event.getMessage()); - } - - @Override - public String getThreadName() - { - return _event.getThreadName(); - } - - @Override - public String getLevel() - { - return _event.getLevel().toString(); - } - - @Override - public String getLoggerName() - { - return _event.getLoggerName(); - } - } - - LinkedList<_Error> _events = new LinkedList<>(); - - @Override - public synchronized void append(LogEvent loggingEvent) - { - if (loggingEvent.getLevel().intLevel() == Level.DEBUG.intLevel()) - return; - clean(); - _events.addFirst(new _Error(loggingEvent)); - } - - private synchronized void clean() - { - long yesterday = HeartBeat.currentTimeMillis() - TimeUnit.DAYS.toMillis(1); - while (_events.size() > 100 || !_events.isEmpty() && _events.getLast()._event.getTimeMillis() < yesterday) - _events.removeLast(); - } - /* ErrorsMXBean */ - - @Override - public synchronized Error[] getErrors() - { - clean(); - return _events.toArray(new _Error[_events.size()]); - } - - @Override - public synchronized Date getTime() - { - return _events.isEmpty() ? null : _events.getFirst().getTime(); - } - - @Override - public synchronized String getMessage() - { - return _events.isEmpty() ? null : _events.getFirst().getMessage(); - } - - @Override - public synchronized String getLevel() - { - return _events.isEmpty() ? null : _events.getFirst().getLevel(); - } - - @Override - public synchronized void clear() - { - _events.clear(); - } -} diff --git a/api/src/org/labkey/api/util/SafeFileAppender.java b/api/src/org/labkey/api/util/SafeFileAppender.java index b607a49cb85..c21de11da78 100644 --- a/api/src/org/labkey/api/util/SafeFileAppender.java +++ b/api/src/org/labkey/api/util/SafeFileAppender.java @@ -15,17 +15,22 @@ */ package org.labkey.api.util; +import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.Core; import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.Layout; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.appender.FileAppender; import org.apache.logging.log4j.core.config.Property; import org.apache.logging.log4j.core.config.plugins.Plugin; import org.apache.logging.log4j.core.config.plugins.PluginAttribute; import org.apache.logging.log4j.core.config.plugins.PluginElement; import org.apache.logging.log4j.core.config.plugins.PluginFactory; +import org.jetbrains.annotations.Nullable; +import org.labkey.api.pipeline.PipelineJob; import java.io.BufferedWriter; import java.io.File; @@ -33,36 +38,46 @@ import java.io.IOException; import java.io.Serializable; +import static org.labkey.api.util.StringUtilsLabKey.DEFAULT_CHARSET; + /** * Custom Log4J appender that opens the log file and closes it for each logging operation, thus ensuring * that the file does not stay locked. * Created: Oct 18, 2005 * @author bmaclean */ -@Plugin(name = "SafeFile", category = "Core", elementType = "appender", printObject = true) +@Plugin(name = FileAppender.PLUGIN_NAME, category = Core.CATEGORY_NAME, elementType = FileAppender.ELEMENT_TYPE, printObject = true) public class SafeFileAppender extends AbstractAppender { private static Logger _log = LogManager.getLogger(SafeFileAppender.class); private final String LINE_SEP = System.getProperty("line.separator"); private static File _file; + @Nullable + private PipelineJob _job; + @Nullable + private Logger _jobLogger; + private boolean _isSettingStatus; - public SafeFileAppender(String name, Filter filter, Layout layout, boolean ignoreExceptions, Property[] properties) + public SafeFileAppender(String name, Filter filter, Layout layout, boolean ignoreExceptions, Property[] properties, @Nullable PipelineJob job) { super(name, filter, layout, ignoreExceptions, properties); + _job = job; + _jobLogger = job != null? job.getClassLogger() : null; } @PluginFactory public static SafeFileAppender createAppender(@PluginAttribute("name") String name, @PluginAttribute("ignoreExceptions") boolean ignoreExceptions, - @PluginElement("Layout") Layout layout, + @PluginElement("Layout") Layout layout, @PluginElement("Filters") Filter filter, - File file) + File file, + @Nullable PipelineJob job) { _file = file; // Make sure that we try to mount the drive (if needed) before using the file NetworkDrive.exists(_file); - return new SafeFileAppender(name, filter, layout, ignoreExceptions, null); + return new SafeFileAppender(name, filter, layout, ignoreExceptions, null, job); } @Override @@ -70,8 +85,24 @@ public void append(LogEvent loggingEvent) { try (BufferedWriter writer = new BufferedWriter(new FileWriter(_file, true))) { - writer.write(loggingEvent.getMessage().getFormattedMessage()); + if (null != _jobLogger) + { + logJobMessage(loggingEvent, loggingEvent.getThrown()); + } + writer.write(new String(getLayout().toByteArray(loggingEvent), DEFAULT_CHARSET)); writer.write(LINE_SEP); + if (null != loggingEvent.getThrown()) + { + StackTraceElement[] stackTraceElements = loggingEvent.getThrown().getStackTrace(); + if (stackTraceElements != null) + { + for (StackTraceElement stackTraceElement : stackTraceElements) + { + writer.write(stackTraceElement.toString()); + writer.write(LINE_SEP); + } + } + } } catch (IOException e) { @@ -83,4 +114,76 @@ public void append(LogEvent loggingEvent) } } + private void logJobMessage(LogEvent logEvent, @Nullable Throwable t) + { + if (logEvent.getLevel().equals(Level.TRACE)) + { + _jobLogger.trace(getSystemLogMessage(logEvent.getMessage()), t); + } + + if (logEvent.getLevel().equals(Level.DEBUG)) + { + _jobLogger.debug(getSystemLogMessage(logEvent.getMessage()), t); + } + + if (logEvent.getLevel().equals(Level.INFO)) + { + _jobLogger.info(getSystemLogMessage(logEvent.getMessage()), t); + } + + if (logEvent.getLevel().equals(Level.WARN)) + { + _jobLogger.warn(getSystemLogMessage(logEvent.getMessage()), t); + } + + if (logEvent.getLevel().equals(Level.ERROR)) + { + _jobLogger.error(getSystemLogMessage(logEvent.getMessage()), t); + setErrorStatus(logEvent.getMessage()); + } + + if (logEvent.getLevel().equals(Level.FATAL)) + { + _jobLogger.fatal(getSystemLogMessage(logEvent.getMessage()), t); + setErrorStatus(logEvent.getMessage()); + } + } + + private String getSystemLogMessage(Object message) + { + StringBuilder sb = new StringBuilder(); + sb.append("(from pipeline job log file "); + sb.append(_file.getPath()); + if (message != null) + { + sb.append(": "); + String stringMessage = message.toString(); + // Limit the maximum line length + final int maxLength = 10000; + if (stringMessage.length() > maxLength) + { + stringMessage = stringMessage.substring(0, maxLength) + "..."; + } + sb.append(stringMessage); + } + sb.append(")"); + return sb.toString(); + } + + public void setErrorStatus(Object message) + { + if (_isSettingStatus) + return; + + _isSettingStatus = true; + try + { + _job.setStatus(PipelineJob.TaskStatus.error, message == null ? "ERROR" : message.toString()); + } + finally + { + _isSettingStatus = false; + } + } + } diff --git a/api/src/org/labkey/api/util/SessionAppender.java b/api/src/org/labkey/api/util/SessionAppender.java index aaf3f5ebc4c..5a1f5eaf0d9 100644 --- a/api/src/org/labkey/api/util/SessionAppender.java +++ b/api/src/org/labkey/api/util/SessionAppender.java @@ -15,30 +15,45 @@ */ package org.labkey.api.util; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Core; import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.Layout; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.appender.AbstractAppender; import org.apache.logging.log4j.core.config.Property; import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.config.plugins.PluginAttribute; +import org.apache.logging.log4j.core.config.plugins.PluginElement; +import org.apache.logging.log4j.core.config.plugins.PluginFactory; import org.jetbrains.annotations.NotNull; import org.springframework.util.ConcurrentReferenceHashMap; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpSession; import java.io.Serializable; -import java.util.LinkedList; -import java.util.List; +import java.util.Collections; import java.util.Map; +import java.util.WeakHashMap; /** * User: matthewb * Date: Aug 18, 2009 * Time: 2:18:21 PM */ -@Plugin(name = "SessionAppender", category = "Core", elementType = "appender", printObject = true) +@Plugin(name = "SessionAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE, printObject = true) public class SessionAppender extends AbstractAppender { + private static ThreadLocal> _eventIds = new ThreadLocal<>(); + + @PluginFactory + public static SessionAppender createAppender(@PluginAttribute("name") String name, + @PluginElement("Layout") Layout layout, + @PluginElement("Filter") final Filter filter) + { + return new SessionAppender(name, filter, layout, false, null); + } + protected SessionAppender(String name, Filter filter, Layout layout, boolean ignoreExceptions, Property[] properties) { super(name, filter, layout, ignoreExceptions, properties); @@ -54,7 +69,7 @@ static class AppenderInfo implements Serializable final String key; boolean on; - final List list = new LinkedList<>(); + final Map eventIdMap = new WeakHashMap<>(); int eventId=0; } @@ -90,25 +105,23 @@ public void append(LogEvent event) AppenderInfo info = localInfo.get(); if (null == info || !info.on) return; - synchronized (info.list) + synchronized (info.eventIdMap) { - // TODO - find replacement - maybe a ThreadLocal using a WeakHashMap of Event->EventId? - // event.setProperty("eventId", String.valueOf(++info.eventId)); - info.list.add(event); - if (info.list.size() > 1000) - info.list.remove(0); + info.eventIdMap.put(event, String.valueOf(++info.eventId)); + if (info.eventIdMap.size() > 1000) + info.eventIdMap.remove(0); } } - public static LogEvent[] getLoggingEvents(HttpServletRequest request) + public static Map getLoggingEvents(HttpServletRequest request) { AppenderInfo info = _getLoggingForSession(request); if (null == info) - return new LogEvent[0]; - synchronized (info.list) + return Collections.emptyMap(); + synchronized (info.eventIdMap) { - return info.list.toArray(new LogEvent[0]); + return info.eventIdMap; } } diff --git a/api/src/org/labkey/api/util/SimpleLoggerWriter.java b/api/src/org/labkey/api/util/SimpleLoggerWriter.java new file mode 100644 index 00000000000..6cf4a0a0207 --- /dev/null +++ b/api/src/org/labkey/api/util/SimpleLoggerWriter.java @@ -0,0 +1,82 @@ +package org.labkey.api.util; + +import org.apache.logging.log4j.Logger; + +/** + * Simple implementation of LoggerWriter that uses the regular logger. + * */ +public class SimpleLoggerWriter implements LoggerWriter +{ + private Logger _log; + + public SimpleLoggerWriter(Logger log) + { + _log = log; + } + + @Override + public void write(String message, Throwable t) + { + + } + + @Override + public void debug(String message) + { + _log.debug(message); + } + + @Override + public void debug(String message, Throwable t) + { + _log.debug(message, t); + } + + @Override + public void error(String message) + { + _log.error(message); + } + + @Override + public void error(String message, Throwable t) + { + _log.error(message, t); + } + + @Override + public void info(String message) + { + _log.info(message); + } + + @Override + public void info(String message, Throwable t) + { + _log.info(message, t); + } + + @Override + public void fatal(String message) + { + _log.fatal(message); + } + + @Override + public void fatal(String message, Throwable t) + { + _log.fatal(message, t); + } + + @Override + public void trace(String message) + { + _log.trace(message); + } + + @Override + public void trace(String message, Throwable t) + { + _log.trace(message, t); + } +} diff --git a/core/resources/scripts/console.js b/core/resources/scripts/console.js index da946aacda4..f288dfc3f2f 100644 --- a/core/resources/scripts/console.js +++ b/core/resources/scripts/console.js @@ -4,7 +4,7 @@ * Licensed under the Apache License, Version 2.0: http://www.apache.org/licenses/LICENSE-2.0 */ -var Logger = org.apache.log4j.Logger; +var LogManager = org.apache.logging.log4j.LogManager; var logger = LogManager.getLogger(org.labkey.api.script.ScriptService.Console); diff --git a/core/src/org/labkey/core/admin/AdminController.java b/core/src/org/labkey/core/admin/AdminController.java index ed2d0d1bb03..7c939545dfc 100644 --- a/core/src/org/labkey/core/admin/AdminController.java +++ b/core/src/org/labkey/core/admin/AdminController.java @@ -7628,17 +7628,17 @@ public ApiResponse execute(Object o, BindException errors) eventId = Integer.parseInt(s); } catch (NumberFormatException x) {} - LogEvent[] events = SessionAppender.getLoggingEvents(getViewContext().getRequest()); - ArrayList> list = new ArrayList<>(events.length); - for (LogEvent e : events) + Map events = SessionAppender.getLoggingEvents(getViewContext().getRequest()); + ArrayList> list = new ArrayList<>(events.size()); + for (Map.Entry entry : events.entrySet()) { - // TODO - find replacement - maybe a ThreadLocal using a WeakHashMap of Event->EventId? -// if (eventId==0 || eventId m = new HashMap<>(); + m.put("eventId", entry.getValue()); m.put("level", e.getLevel().toString()); - m.put("message", e.getMessage()); + m.put("message", e.getMessage().getFormattedMessage()); m.put("timestamp", new Date(e.getTimeMillis())); list.add(m); } diff --git a/core/src/org/labkey/core/admin/logger/LoggerController.java b/core/src/org/labkey/core/admin/logger/LoggerController.java index e3e926160db..008ad46a00b 100644 --- a/core/src/org/labkey/core/admin/logger/LoggerController.java +++ b/core/src/org/labkey/core/admin/logger/LoggerController.java @@ -23,7 +23,6 @@ import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.Configurator; import org.apache.logging.log4j.core.config.LoggerConfig; -import org.apache.logging.log4j.core.config.NullConfiguration; import org.labkey.api.action.FormViewAction; import org.labkey.api.action.Marshal; import org.labkey.api.action.Marshaller; @@ -49,9 +48,11 @@ import org.springframework.validation.Errors; import org.springframework.web.servlet.ModelAndView; -import java.net.URL; -import java.util.ArrayList; +import java.net.URISyntaxException; import java.util.Collection; +import java.util.HashSet; +import java.util.Objects; +import java.util.Set; /** * User: kevink @@ -83,17 +84,30 @@ public static class LoggerLevel private String level; private boolean inherited; - public static LoggerLevel fromLogger(LoggerConfig log) + public static LoggerLevel fromLoggerConfig(LoggerConfig log) { LoggerConfig parent = log.getParent(); - Level level = log.getLevel(); - Level effectiveLevel = log.getLevel(); + String parentName = parent != null ? parent.getName() : ""; + return getLoggerLevel(parentName, log.getLevel(), log.getName()); + } + + public static LoggerLevel fromLogger(Logger log) + { + Logger parent = ((org.apache.logging.log4j.core.Logger) log).getParent(); + String parentName = parent != null ? parent.getName() : null; + + return getLoggerLevel(parentName, log.getLevel(), log.getName()); + } + + private static LoggerLevel getLoggerLevel(String parent, Level level, String name) + { LoggerLevel loggerLevel = new LoggerLevel(); - loggerLevel.setName(log.getName()); - loggerLevel.setParent(parent != null ? parent.getName() : null); - loggerLevel.setLevel(level != null ? level.toString() : effectiveLevel.toString()); - loggerLevel.setInherited(level == null); + loggerLevel.setName(name); + loggerLevel.setParent(parent); + loggerLevel.setLevel(level.toString()); + boolean inherited = parent != null && !parent.equalsIgnoreCase(name); + loggerLevel.setInherited(inherited); return loggerLevel; } @@ -136,6 +150,24 @@ public void setInherited(boolean inherited) { this.inherited = inherited; } + + @Override + public boolean equals(Object o) + { + if (this == o) return true; + if (o == null || getClass() != o.getClass()) return false; + LoggerLevel that = (LoggerLevel) o; + return inherited == that.inherited && + name.equals(that.name) && + Objects.equals(parent, that.parent) && + level.equals(that.level); + } + + @Override + public int hashCode() + { + return Objects.hash(name, parent, level, inherited); + } } public static class ListFilter @@ -181,23 +213,24 @@ public class ListAction extends ReadOnlyApiAction @Override public SimpleResponse> execute(ListFilter filter, BindException errors) { - Level filterLevel = filter.getLevel() != null ? Level.toLevel(filter.getLevel()) : null; - - Collection loggers = new ArrayList<>(); - LoggerContext loggerContext = (LoggerContext) LogManager.getContext(true); + Set loggers = new HashSet<>(); + LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false); Configuration configuration = loggerContext.getConfiguration(); + Collection currentLoggers = loggerContext.getLoggers(); + Collection loggerConfigs = configuration.getLoggers().values(); - Collection currentLoggers = configuration.getLoggers().values(); - for (LoggerConfig currentLogger: currentLoggers) + for (LoggerConfig currentLogger: loggerConfigs) { - if (!filter.isInherited() && currentLogger.getLevel() == null) + if (filterCheck(filter, currentLogger.getLevel(), currentLogger.getName())) continue; - if (filterLevel != null && !(filterLevel.equals(currentLogger.getLevel()))) - continue; + loggers.add(LoggerLevel.fromLoggerConfig(currentLogger)); + } - if (filter.getContains() != null && !StringUtils.containsIgnoreCase(currentLogger.getName(), filter.getContains())) + for (Logger currentLogger: currentLoggers) + { + if (filterCheck(filter, currentLogger.getLevel(), currentLogger.getName())) continue; loggers.add(LoggerLevel.fromLogger(currentLogger)); @@ -205,18 +238,28 @@ public SimpleResponse> execute(ListFilter filter, BindEx return success(loggers); } + + private boolean filterCheck(ListFilter filter, Level level, String loggerName) + { + Level filterLevel = filter.getLevel() != null ? Level.toLevel(filter.getLevel()) : null; + + if (!filter.isInherited() && level == null) + return true; + + if (filterLevel != null && !(filterLevel.equals(level))) + return true; + + return filter.getContains() != null && !StringUtils.containsIgnoreCase(loggerName, filter.getContains()); + } } @RequiresPermission(AdminOperationsPermission.class) public class ResetAction extends MutatingApiAction { @Override - public SimpleResponse execute(Object o, BindException errors) + public SimpleResponse execute(Object o, BindException errors) throws URISyntaxException { - LoggerContext.getContext(true).setConfiguration(new NullConfiguration()); - URL url = getClass().getResource("/log4j.xml"); - // TODO : log4j -// DOMConfigurator.configure(url); + ((org.apache.logging.log4j.core.LoggerContext) LogManager.getContext(false)).reconfigure(); return success(); } } @@ -237,10 +280,7 @@ public SimpleResponse execute(LoggerLevel loggerLevel, BindExceptio Configurator.setLevel(logger.getName(), Level.toLevel(loggerLevel.level)); } - LoggerContext loggerContext = (LoggerContext) LogManager.getContext(true); - Configuration configuration = loggerContext.getConfiguration(); - - return success(LoggerLevel.fromLogger(configuration.getLoggerConfig(logger.getName()))); + return success(LoggerLevel.fromLogger(logger)); } }