diff --git a/frontend/archive/build.gradle b/frontend/archive/build.gradle index b8d6e992a4..cce015aa26 100644 --- a/frontend/archive/build.gradle +++ b/frontend/archive/build.gradle @@ -1,7 +1,7 @@ dependencies { api "commons-io:commons-io:2.6" api "org.slf4j:slf4j-api:${slf4j_api_version}" - api "org.slf4j:slf4j-log4j12:${slf4j_log4j12_version}" + api "org.apache.logging.log4j:log4j-slf4j-impl:${slf4j_log4j_version}" api "com.google.code.gson:gson:${gson_version}" testImplementation "commons-cli:commons-cli:${commons_cli_version}" diff --git a/frontend/build.gradle b/frontend/build.gradle index ecf62bcd0a..2feaef8a7a 100644 --- a/frontend/build.gradle +++ b/frontend/build.gradle @@ -59,7 +59,7 @@ configure(javaProjects()) { test.finalizedBy(project.tasks.jacocoTestReport) compileJava { - options.compilerArgs << "-Xlint:all,-options,-static" << "-Werror" + options.compilerArgs << "-proc:none" << "-Xlint:all,-options,-static" << "-Werror" } jacocoTestCoverageVerification { diff --git a/frontend/gradle.properties b/frontend/gradle.properties index ed190933df..1b6370362b 100644 --- a/frontend/gradle.properties +++ b/frontend/gradle.properties @@ -4,10 +4,10 @@ commons_cli_version=1.3.1 gson_version=2.8.5 prometheus_version=0.9.0 netty_version=4.1.53.Final -slf4j_api_version=1.7.25 -slf4j_log4j12_version=1.7.25 +slf4j_api_version=1.7.32 +slf4j_log4j_version=2.16.0 testng_version=7.1.0 torchserve_sdk_version=0.0.4 snakeyaml_version=1.8 grpc_version=1.31.1 -protoc_version=3.13.0 +protoc_version=3.13.0 \ No newline at end of file diff --git a/frontend/server/build.gradle b/frontend/server/build.gradle index 9076e8d257..a1382f75d6 100644 --- a/frontend/server/build.gradle +++ b/frontend/server/build.gradle @@ -6,6 +6,7 @@ dependencies { implementation project(":archive") implementation "commons-cli:commons-cli:${commons_cli_version}" implementation "org.pytorch:torchserve-plugins-sdk:${torchserve_sdk_version}" + implementation "org.apache.logging.log4j:log4j-core:${slf4j_log4j_version}" testImplementation "org.testng:testng:${testng_version}" } @@ -26,8 +27,10 @@ jar { exclude "META-INF//NOTICE*" } -test.doFirst { - systemProperty "tsConfigFile", 'src/test/resources/config.properties' - systemProperty "METRICS_LOCATION","build/logs" - systemProperty "LOG_LOCATION","build/logs" -} +test { + doFirst { + systemProperty "tsConfigFile", 'src/test/resources/config.properties' + } + environment "METRICS_LOCATION","build/logs" + environment "LOG_LOCATION","build/logs" +} \ No newline at end of file diff --git a/frontend/server/src/main/java/org/pytorch/serve/job/GRPCJob.java b/frontend/server/src/main/java/org/pytorch/serve/job/GRPCJob.java index d7a90e01ac..102ca7043f 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/job/GRPCJob.java +++ b/frontend/server/src/main/java/org/pytorch/serve/job/GRPCJob.java @@ -17,8 +17,8 @@ public class GRPCJob extends Job { private static final Logger logger = LoggerFactory.getLogger(Job.class); - private static final org.apache.log4j.Logger loggerTsMetrics = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + private static final Logger loggerTsMetrics = + LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); private static final Dimension DIMENSION = new Dimension("Level", "Host"); private StreamObserver predictionResponseObserver; @@ -55,6 +55,7 @@ public void response( TimeUnit.MILLISECONDS.convert( getScheduled() - getBegin(), TimeUnit.NANOSECONDS)); loggerTsMetrics.info( + "{}", new Metric( "QueueTime", queueTime, diff --git a/frontend/server/src/main/java/org/pytorch/serve/job/RestJob.java b/frontend/server/src/main/java/org/pytorch/serve/job/RestJob.java index e65e04680b..644f999d69 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/job/RestJob.java +++ b/frontend/server/src/main/java/org/pytorch/serve/job/RestJob.java @@ -23,8 +23,8 @@ public class RestJob extends Job { private static final Logger logger = LoggerFactory.getLogger(Job.class); - private static final org.apache.log4j.Logger loggerTsMetrics = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + private static final Logger loggerTsMetrics = + LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); private static final Dimension DIMENSION = new Dimension("Level", "Host"); private ChannelHandlerContext ctx; @@ -87,6 +87,7 @@ public void response( TimeUnit.MILLISECONDS.convert( getScheduled() - getBegin(), TimeUnit.NANOSECONDS)); loggerTsMetrics.info( + "{}", new Metric( "QueueTime", queueTime, diff --git a/frontend/server/src/main/java/org/pytorch/serve/metrics/MetricCollector.java b/frontend/server/src/main/java/org/pytorch/serve/metrics/MetricCollector.java index 7aef927c25..de8cf9e0e8 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/metrics/MetricCollector.java +++ b/frontend/server/src/main/java/org/pytorch/serve/metrics/MetricCollector.java @@ -20,8 +20,8 @@ public class MetricCollector implements Runnable { private static final Logger logger = LoggerFactory.getLogger(MetricCollector.class); - private static final org.apache.log4j.Logger loggerMetrics = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + private static final Logger loggerMetrics = + LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); private ConfigManager configManager; public MetricCollector(ConfigManager configManager) { @@ -77,7 +77,7 @@ public void run() { if (metric == null) { logger.warn("Parse metrics failed: " + line); } else { - loggerMetrics.info(metric); + loggerMetrics.info("{}", metric); metricsSystem.add(metric); } } diff --git a/frontend/server/src/main/java/org/pytorch/serve/util/ConfigManager.java b/frontend/server/src/main/java/org/pytorch/serve/util/ConfigManager.java index 7c29879e59..7a11de5bbc 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/util/ConfigManager.java +++ b/frontend/server/src/main/java/org/pytorch/serve/util/ConfigManager.java @@ -43,11 +43,9 @@ import org.apache.commons.cli.Option; import org.apache.commons.cli.Options; import org.apache.commons.io.IOUtils; -import org.apache.log4j.Appender; -import org.apache.log4j.AsyncAppender; -import org.apache.log4j.Logger; import org.pytorch.serve.servingsdk.snapshot.SnapshotSerializer; import org.pytorch.serve.snapshot.SnapshotSerializerFactory; +import org.slf4j.LoggerFactory; public final class ConfigManager { // Variables that can be configured through config.properties and Environment Variables @@ -692,30 +690,9 @@ private File findTsHome() { } private void enableAsyncLogging() { - enableAsyncLogging(Logger.getRootLogger()); - enableAsyncLogging(Logger.getLogger(MODEL_METRICS_LOGGER)); - enableAsyncLogging(Logger.getLogger(MODEL_LOGGER)); - enableAsyncLogging(Logger.getLogger(MODEL_SERVER_METRICS_LOGGER)); - enableAsyncLogging(Logger.getLogger("ACCESS_LOG")); - enableAsyncLogging(Logger.getLogger("org.pytorch.serve")); - } - - private void enableAsyncLogging(Logger logger) { - AsyncAppender asyncAppender = new AsyncAppender(); - - @SuppressWarnings("unchecked") - Enumeration en = logger.getAllAppenders(); - while (en.hasMoreElements()) { - Appender appender = en.nextElement(); - if (appender instanceof AsyncAppender) { - // already async - return; - } - - logger.removeAppender(appender); - asyncAppender.addAppender(appender); - } - logger.addAppender(asyncAppender); + System.setProperty( + "log4j2.contextSelector", + "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector"); } public HashMap getBackendConfiguration() { @@ -836,14 +813,12 @@ public int getJsonIntValue(String modelName, String version, String element, int value = defaultVal; } } catch (ClassCastException | IllegalStateException e) { - Logger.getRootLogger() + LoggerFactory.getLogger(ConfigManager.class) .error( - "Invalid value for model: " - + modelName - + ":" - + version - + ", parameter: " - + element); + "Invalid value for model: {}:{}, parameter: {}", + modelName, + version, + element); return defaultVal; } } diff --git a/frontend/server/src/main/java/org/pytorch/serve/util/NettyUtils.java b/frontend/server/src/main/java/org/pytorch/serve/util/NettyUtils.java index c2bb18af40..31d873d02d 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/util/NettyUtils.java +++ b/frontend/server/src/main/java/org/pytorch/serve/util/NettyUtils.java @@ -63,8 +63,8 @@ public final class NettyUtils { ConfigManager.getInstance().getHostName(), DIMENSION); - private static final org.apache.log4j.Logger loggerTsMetrics = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + private static final Logger loggerTsMetrics = + LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); private NettyUtils() {} @@ -157,11 +157,11 @@ public static void sendHttpResponse( } int code = resp.status().code(); if (code >= 200 && code < 300) { - loggerTsMetrics.info(REQUESTS_2_XX); + loggerTsMetrics.info("{}", REQUESTS_2_XX); } else if (code >= 400 && code < 500) { - loggerTsMetrics.info(REQUESTS_4_XX); + loggerTsMetrics.info("{}", REQUESTS_4_XX); } else { - loggerTsMetrics.info(REQUESTS_5_XX); + loggerTsMetrics.info("{}", REQUESTS_5_XX); } String allowedOrigin = configManager.getCorsAllowedOrigin(); diff --git a/frontend/server/src/main/java/org/pytorch/serve/util/logging/JSONLayout.java b/frontend/server/src/main/java/org/pytorch/serve/util/logging/JSONLayout.java deleted file mode 100644 index d32a1aeacf..0000000000 --- a/frontend/server/src/main/java/org/pytorch/serve/util/logging/JSONLayout.java +++ /dev/null @@ -1,22 +0,0 @@ -package org.pytorch.serve.util.logging; - -import org.apache.log4j.PatternLayout; -import org.apache.log4j.spi.LoggingEvent; -import org.pytorch.serve.metrics.Metric; -import org.pytorch.serve.util.JsonUtils; - -public class JSONLayout extends PatternLayout { - - @Override - public String format(LoggingEvent event) { - Object eventMessage = event.getMessage(); - if (eventMessage == null) { - return null; - } - if (eventMessage instanceof Metric) { - Metric metric = (Metric) event.getMessage(); - return JsonUtils.GSON_PRETTY.toJson(metric) + '\n'; - } - return eventMessage.toString() + '\n'; - } -} diff --git a/frontend/server/src/main/java/org/pytorch/serve/util/logging/QLogLayout.java b/frontend/server/src/main/java/org/pytorch/serve/util/logging/QLogLayout.java index 338832e480..3dab543feb 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/util/logging/QLogLayout.java +++ b/frontend/server/src/main/java/org/pytorch/serve/util/logging/QLogLayout.java @@ -1,11 +1,23 @@ package org.pytorch.serve.util.logging; -import org.apache.log4j.PatternLayout; -import org.apache.log4j.spi.LoggingEvent; +import org.apache.logging.log4j.core.Layout; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.config.Node; +import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.layout.AbstractStringLayout; +import org.apache.logging.log4j.message.Message; import org.pytorch.serve.metrics.Dimension; import org.pytorch.serve.metrics.Metric; -public class QLogLayout extends PatternLayout { +@Plugin( + name = "QLogLayout", + category = Node.CATEGORY, + elementType = Layout.ELEMENT_TYPE, + printObject = true) +public class QLogLayout extends AbstractStringLayout { + public QLogLayout() { + super(null, null, null); + } /** * Model server also supports query log formatting. @@ -61,67 +73,68 @@ public class QLogLayout extends PatternLayout { * @return */ @Override - public String format(LoggingEvent event) { - Object eventMessage = event.getMessage(); + public String toSerializable(LogEvent event) { + Message eventMessage = event.getMessage(); + if (eventMessage == null || eventMessage.getParameters() == null) { + return null; + } String programName = getStringOrDefault(System.getenv("MXNETMODELSERVER_PROGRAM"), "MXNetModelServer"); String domain = getStringOrDefault(System.getenv("DOMAIN"), "Unknown"); long currentTimeInSec = System.currentTimeMillis() / 1000; + Object[] parameters = eventMessage.getParameters(); - if (eventMessage == null) { - return null; - } - if (eventMessage instanceof Metric) { - String marketPlace = System.getenv("REALM"); + StringBuilder stringBuilder = new StringBuilder(); + for (Object obj : parameters) { + if (obj instanceof Metric) { + Metric metric = (Metric) obj; + String marketPlace = System.getenv("REALM"); - StringBuilder stringBuilder = new StringBuilder(); - Metric metric = (Metric) eventMessage; - stringBuilder.append("HostName=").append(metric.getHostName()); + stringBuilder.append("HostName=").append(metric.getHostName()); - if (metric.getRequestId() != null && !metric.getRequestId().isEmpty()) { - stringBuilder.append("\nRequestId=").append(metric.getRequestId()); - } + if (metric.getRequestId() != null && !metric.getRequestId().isEmpty()) { + stringBuilder.append("\nRequestId=").append(metric.getRequestId()); + } - // Marketplace format should be : :: - if (marketPlace != null && !marketPlace.isEmpty()) { - stringBuilder - .append("\nMarketplace=") - .append(programName) - .append(':') - .append(domain) - .append(':') - .append(marketPlace); - } + // Marketplace format should be : :: + if (marketPlace != null && !marketPlace.isEmpty()) { + stringBuilder + .append("\nMarketplace=") + .append(programName) + .append(':') + .append(domain) + .append(':') + .append(marketPlace); + } - stringBuilder - .append("\nStartTime=") - .append( - getStringOrDefault( - metric.getTimestamp(), Long.toString(currentTimeInSec))); + stringBuilder + .append("\nStartTime=") + .append( + getStringOrDefault( + metric.getTimestamp(), Long.toString(currentTimeInSec))); - stringBuilder - .append("\nProgram=") - .append(programName) - .append("\nMetrics=") - .append(metric.getMetricName()) - .append('=') - .append(metric.getValue()) - .append(' ') - .append(metric.getUnit()); - for (Dimension dimension : metric.getDimensions()) { stringBuilder + .append("\nProgram=") + .append(programName) + .append("\nMetrics=") + .append(metric.getMetricName()) + .append('=') + .append(metric.getValue()) .append(' ') - .append(dimension.getName()) - .append('|') - .append(dimension.getValue()) - .append(' '); + .append(metric.getUnit()); + for (Dimension dimension : metric.getDimensions()) { + stringBuilder + .append(' ') + .append(dimension.getName()) + .append('|') + .append(dimension.getValue()) + .append(' '); + } + stringBuilder.append("\nEOE\n"); } - stringBuilder.append("\nEOE\n"); - - return stringBuilder.toString(); } - return eventMessage.toString(); + return stringBuilder.toString(); } private static String getStringOrDefault(String val, String defVal) { diff --git a/frontend/server/src/main/java/org/pytorch/serve/wlm/WorkerThread.java b/frontend/server/src/main/java/org/pytorch/serve/wlm/WorkerThread.java index 6ec5db67e4..55e7ef29aa 100644 --- a/frontend/server/src/main/java/org/pytorch/serve/wlm/WorkerThread.java +++ b/frontend/server/src/main/java/org/pytorch/serve/wlm/WorkerThread.java @@ -41,8 +41,8 @@ public class WorkerThread implements Runnable { private static final Logger logger = LoggerFactory.getLogger(WorkerThread.class); - private static final org.apache.log4j.Logger loggerTsMetrics = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + private static final Logger loggerTsMetrics = + LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); private Metric workerLoadTime; @@ -221,6 +221,7 @@ public void run() { String workerThreadTime = String.valueOf(((System.currentTimeMillis() - wtStartTime) - duration)); loggerTsMetrics.info( + "{}", new Metric( "WorkerThreadTime", workerThreadTime, @@ -412,7 +413,7 @@ public void setState(WorkerState newState, int status) { workerLoadTime.setValue(String.valueOf(timeTaken)); workerLoadTime.setTimestamp( String.valueOf(TimeUnit.MILLISECONDS.toSeconds(System.currentTimeMillis()))); - loggerTsMetrics.info(workerLoadTime); + loggerTsMetrics.info("{}", workerLoadTime); } } diff --git a/frontend/server/src/main/resources/log4j2.xml b/frontend/server/src/main/resources/log4j2.xml new file mode 100644 index 0000000000..0e3e459b32 --- /dev/null +++ b/frontend/server/src/main/resources/log4j2.xml @@ -0,0 +1,85 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/frontend/server/src/test/java/org/pytorch/serve/util/ConfigManagerTest.java b/frontend/server/src/test/java/org/pytorch/serve/util/ConfigManagerTest.java index 7fe3dab8b5..15daf18dad 100644 --- a/frontend/server/src/test/java/org/pytorch/serve/util/ConfigManagerTest.java +++ b/frontend/server/src/test/java/org/pytorch/serve/util/ConfigManagerTest.java @@ -69,13 +69,12 @@ public void test() throws IOException, GeneralSecurityException, ReflectiveOpera metrics.add(createMetric("TestMetric1", "12345")); metrics.add(createMetric("TestMetric2", "23478")); - org.apache.log4j.Logger logger = - org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); - logger.debug(metrics); + Logger logger = LoggerFactory.getLogger(ConfigManager.MODEL_SERVER_METRICS_LOGGER); + logger.debug("{}", metrics); Assert.assertTrue(new File("build/logs/ts_metrics.log").exists()); - logger = org.apache.log4j.Logger.getLogger(ConfigManager.MODEL_METRICS_LOGGER); - logger.debug(metrics); + logger = LoggerFactory.getLogger(ConfigManager.MODEL_METRICS_LOGGER); + logger.debug("{}", metrics); Assert.assertTrue(new File("build/logs/model_metrics.log").exists()); Logger modelLogger = LoggerFactory.getLogger(ConfigManager.MODEL_LOGGER); diff --git a/frontend/server/src/test/resources/config.properties b/frontend/server/src/test/resources/config.properties index 1c433b2775..7b8f3e29a2 100644 --- a/frontend/server/src/test/resources/config.properties +++ b/frontend/server/src/test/resources/config.properties @@ -28,6 +28,7 @@ max_request_size=2047093252 # blacklist_env_vars=.*USERNAME.*|.*PASSWORD.* # decode_input_request=true enable_envvars_config=true +# default_service_handler=/path/to/service.py:handle models={\ "noop": {\ "1.11": {\