diff --git a/build.gradle b/build.gradle index d5beeab03..b84eae547 100644 --- a/build.gradle +++ b/build.gradle @@ -75,6 +75,7 @@ dependencies { compile 'commons-io:commons-io:2.6' compile 'org.springframework:spring-context:5.0.5.RELEASE' compile 'org.aspectj:aspectjweaver:1.9.1' + compile 'org.slf4j:slf4j-api:1.7.25' testCompile 'junit:junit:4.12' testCompile 'org.hamcrest:hamcrest-library:1.3' diff --git a/src/main/java/io/appium/java_client/service/local/AppiumDriverLocalService.java b/src/main/java/io/appium/java_client/service/local/AppiumDriverLocalService.java index f1c19abbd..51e6620cf 100644 --- a/src/main/java/io/appium/java_client/service/local/AppiumDriverLocalService.java +++ b/src/main/java/io/appium/java_client/service/local/AppiumDriverLocalService.java @@ -17,7 +17,10 @@ package io.appium.java_client.service.local; import static com.google.common.base.Preconditions.checkNotNull; +import static org.slf4j.event.Level.DEBUG; +import static org.slf4j.event.Level.INFO; +import com.google.common.annotations.VisibleForTesting; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; @@ -26,6 +29,9 @@ import org.openqa.selenium.net.UrlChecker; import org.openqa.selenium.os.CommandLine; import org.openqa.selenium.remote.service.DriverService; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.event.Level; import java.io.File; import java.io.IOException; @@ -35,11 +41,20 @@ import java.util.List; import java.util.concurrent.TimeUnit; import java.util.concurrent.locks.ReentrantLock; +import java.util.function.BiConsumer; +import java.util.function.Consumer; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + import javax.annotation.Nullable; public final class AppiumDriverLocalService extends DriverService { private static final String URL_MASK = "http://%s:%d/wd/hub"; + private static final Logger LOG = LoggerFactory.getLogger(AppiumDriverLocalService.class); + private static final Pattern LOG_MESSAGE_PATTERN = Pattern.compile("^(.*)\\R"); + private static final Pattern LOGGER_CONTEXT_PATTERN = Pattern.compile("^(\\[debug\\] )?\\[(.+?)\\]"); + private static final String APPIUM_SERVICE_SLF4J_LOGGER_PREFIX = "appium.service"; private final File nodeJSExec; private final ImmutableList nodeJSArgs; private final ImmutableMap nodeJSEnvironment; @@ -219,4 +234,134 @@ public void addOutPutStreams(List outputStreams) { public boolean clearOutPutStreams() { return stream.clear(); } + + /** + * Enables server output data logging through + * SLF4J loggers. This allow server output + * data to be configured with your preferred logging frameworks (e.g. + * java.util.logging, logback, log4j). + * + *

NOTE1: You might want to call method {@link #clearOutPutStreams()} before + * calling this method.
+ * NOTE2: it is required that {@code --log-timestamp} server flag is + * {@code false}. + * + *

By default log messages are: + *

    + *
  • logged at {@code INFO} level, unless log message is pre-fixed by + * {@code [debug]} then logged at {@code DEBUG} level.
    • + *
  • logged by a SLF4J logger instance with + * a name corresponding to the appium sub module as prefixed in log message + * (logger name is transformed to lower case, no spaces and prefixed with + * "appium.service.").
    • + *
+ * Example log-message: "[ADB] Cannot read version codes of " is logged by + * logger: {@code appium.service.adb} at level {@code INFO}. + *
+ * Example log-message: "[debug] [XCUITest] Xcode version set to 'x.y.z' " + * is logged by logger {@code appium.service.xcuitest} at level + * {@code DEBUG}. + *
+ * + * @see #addSlf4jLogMessageConsumer(BiConsumer) + */ + public void enableDefaultSlf4jLoggingOfOutputData() { + addSlf4jLogMessageConsumer((logMessage, ctx) -> { + if (ctx.getLevel().equals(DEBUG)) { + ctx.getLogger().debug(logMessage); + } else { + ctx.getLogger().info(logMessage); + } + }); + } + + /** + * When a complete log message is available (from server output data) that + * message is parsed for its slf4j context (logger name, logger level etc.) + * and the specified {@code BiConsumer} is invoked with the log message and + * slf4j context. + * + *

Use this method only if you want a behavior that differentiates from the + * default behavior as enabled by method + * {@link #enableDefaultSlf4jLoggingOfOutputData()}. + * + *

NOTE: You might want to call method {@link #clearOutPutStreams()} before + * calling this method. + * + *

implementation detail: + *

    + *
  • if log message begins with {@code [debug]} then log level is set to + * {@code DEBUG}, otherwise log level is {@code INFO}.
    • + *
  • the appium sub module name is parsed from the log message and used as + * logger name (prefixed with "appium.service.", all lower case, spaces + * removed). If no appium sub module is detected then "appium.service" is + * used as logger name.
    • + *
+ * Example log-message: "[ADB] Cannot read version codes of " is logged by + * {@code appium.service.adb} at level {@code INFO}
+ * Example log-message: "[debug] [XCUITest] Xcode version set to 'x.y.z' " + * is logged by {@code appium.service.xcuitest} at level {@code DEBUG} + *
+ * + * @param slf4jLogMessageConsumer + * BiConsumer block to be executed when a log message is + * available. + */ + public void addSlf4jLogMessageConsumer(BiConsumer slf4jLogMessageConsumer) { + checkNotNull(slf4jLogMessageConsumer, "slf4jLogMessageConsumer parameter is NULL!"); + addLogMessageConsumer(logMessage -> { + slf4jLogMessageConsumer.accept(logMessage, parseSlf4jContextFromLogMessage(logMessage)); + }); + } + + @VisibleForTesting + static Slf4jLogMessageContext parseSlf4jContextFromLogMessage(String logMessage) { + Matcher m = LOGGER_CONTEXT_PATTERN.matcher(logMessage); + String loggerName = APPIUM_SERVICE_SLF4J_LOGGER_PREFIX; + Level level = INFO; + if (m.find()) { + loggerName += "." + m.group(2).toLowerCase().replaceAll("\\s+", ""); + if (m.group(1) != null) { + level = DEBUG; + } + } + return new Slf4jLogMessageContext(loggerName, level); + } + + /** + * When a complete log message is available (from server output data), the + * specified {@code Consumer} is invoked with that log message. + * + *

NOTE: You might want to call method {@link #clearOutPutStreams()} before + * calling this method. + * + *

If the Consumer fails and throws an exception the exception is logged (at + * WARN level) and execution continues. + *
+ * + * @param consumer + * Consumer block to be executed when a log message is available. + * + */ + public void addLogMessageConsumer(Consumer consumer) { + checkNotNull(consumer, "consumer parameter is NULL!"); + addOutPutStream(new OutputStream() { + StringBuilder lineBuilder = new StringBuilder(); + + @Override + public void write(int chr) throws IOException { + try { + lineBuilder.append((char) chr); + Matcher matcher = LOG_MESSAGE_PATTERN.matcher(lineBuilder.toString()); + if (matcher.matches()) { + consumer.accept(matcher.group(1)); + lineBuilder = new StringBuilder(); + } + } catch (Exception e) { + // log error and continue + LOG.warn("Log message consumer crashed!", e); + } + } + }); + } } diff --git a/src/main/java/io/appium/java_client/service/local/Slf4jLogMessageContext.java b/src/main/java/io/appium/java_client/service/local/Slf4jLogMessageContext.java new file mode 100644 index 000000000..1e65f940d --- /dev/null +++ b/src/main/java/io/appium/java_client/service/local/Slf4jLogMessageContext.java @@ -0,0 +1,47 @@ +package io.appium.java_client.service.local; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.event.Level; + +/** + * This class provides context to a Slf4jLogMessageConsumer. + * + */ +public final class Slf4jLogMessageContext { + private final Logger logger; + private final Level level; + + Slf4jLogMessageContext(String loggerName, Level level) { + this.level = level; + this.logger = LoggerFactory.getLogger(loggerName); + } + + /** + * Returns the {@link Logger} instance associated with this context. + * + * @return {@link Logger} instance associated with this context. + * + */ + public Logger getLogger() { + return logger; + } + + /** + * Returns log {@link Level} for the log message associated with this context. + * + * @return {@link Level} for log message associated with this context. + */ + public Level getLevel() { + return level; + } + + /** + * Returns the name of the {@link Logger} associated with this context. + * + * @return name of {@link Logger} associated with this context. + */ + public String getName() { + return logger.getName(); + } +} diff --git a/src/test/java/io/appium/java_client/service/local/AppiumDriverLocalServiceTest.java b/src/test/java/io/appium/java_client/service/local/AppiumDriverLocalServiceTest.java new file mode 100644 index 000000000..c0aca9102 --- /dev/null +++ b/src/test/java/io/appium/java_client/service/local/AppiumDriverLocalServiceTest.java @@ -0,0 +1,40 @@ +package io.appium.java_client.service.local; + +import static io.appium.java_client.service.local.AppiumDriverLocalService.parseSlf4jContextFromLogMessage; +import static org.junit.Assert.assertEquals; +import static org.slf4j.LoggerFactory.getLogger; +import static org.slf4j.event.Level.DEBUG; +import static org.slf4j.event.Level.INFO; + +import org.junit.Test; +import org.slf4j.event.Level; + +public class AppiumDriverLocalServiceTest { + + @Test + public void canParseSlf4jLoggerContext() throws Exception { + assertLoggerContext(INFO, "appium.service.androidbootstrap", + "[AndroidBootstrap] [BOOTSTRAP LOG] [debug] json loading complete."); + assertLoggerContext(INFO, "appium.service.adb", + "[ADB] Cannot read version codes of "); + assertLoggerContext(INFO, "appium.service.xcuitest", + "[XCUITest] Determining device to run tests on: udid: '1234567890', real device: true"); + assertLoggerContext(INFO, "appium.service", + "no-prefix log message."); + assertLoggerContext(INFO, "appium.service", + "no-prefix log [not-a-logger-name] message."); + assertLoggerContext(DEBUG, "appium.service.mjsonwp", + "[debug] [MJSONWP] Calling AppiumDriver.getStatus() with args: []"); + assertLoggerContext(DEBUG, "appium.service.xcuitest", + "[debug] [XCUITest] Xcode version set to 'x.y.z' "); + assertLoggerContext(DEBUG, "appium.service.jsonwpproxy", + "[debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:18218/status] with no body"); + } + + private void assertLoggerContext(Level expectedLevel, String expectedLoggerName, String logMessage) { + Slf4jLogMessageContext ctx = parseSlf4jContextFromLogMessage(logMessage); + assertEquals(expectedLoggerName, ctx.getName()); + assertEquals(expectedLevel, ctx.getLevel()); + assertEquals(getLogger(expectedLoggerName), ctx.getLogger()); + } +} diff --git a/src/test/java/io/appium/java_client/service/local/ServerBuilderTest.java b/src/test/java/io/appium/java_client/service/local/ServerBuilderTest.java index 74bef8e9e..4fcb5773a 100644 --- a/src/test/java/io/appium/java_client/service/local/ServerBuilderTest.java +++ b/src/test/java/io/appium/java_client/service/local/ServerBuilderTest.java @@ -39,6 +39,7 @@ import java.net.InetAddress; import java.net.NetworkInterface; import java.nio.file.Path; +import java.util.ArrayList; import java.util.Enumeration; import java.util.List; @@ -114,6 +115,15 @@ public void tearDown() throws Exception { ofNullable(PATH_TO_APPIUM_NODE_IN_PROPERTIES).ifPresent(s -> setProperty(APPIUM_PATH, s)); } + @Test public void checkAbilityToAddLogMessageConsumer() { + List log = new ArrayList<>(); + service = buildDefaultService(); + service.clearOutPutStreams(); + service.addLogMessageConsumer(log::add); + service.start(); + assertTrue(log.size() > 0); + } + @Test public void checkAbilityToStartDefaultService() { service = buildDefaultService(); service.start();