Add SLF4J logging support for Appium local service (#1014)

* Add support for logging appium server output data through SLF4J.

* Format changes

* minor changes

* format changes

* added dependency to alf4j-api

* name changes

* Fixed review comments.

* Fixed indentation.

* more indentation fixes.

* Fixed javadoc errors.

* more javadoc fixes.

* added null check of method arguments.

* Added @VisibleForTesting annotation to avoid codacy warning.

Author: alexander-poulikakos

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'

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<String> nodeJSArgs;
     private final ImmutableMap<String, String> nodeJSEnvironment;
@@ -219,4 +234,134 @@ public void addOutPutStreams(List<OutputStream> outputStreams) {
     public boolean clearOutPutStreams() {
         return stream.clear();
     }
+
+    /**
+     * Enables server output data logging through
+     * <a href="http://slf4j.org">SLF4J</a> loggers. This allow server output
+     * data to be configured with your preferred logging frameworks (e.g.
+     * java.util.logging, logback, log4j).
+     * 
+     * <p>NOTE1: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method.<br>
+     * NOTE2: it is required that {@code --log-timestamp} server flag is
+     * {@code false}.
+     * 
+     * <p>By default log messages are:
+     * <ul>
+     * <li>logged at {@code INFO} level, unless log message is pre-fixed by
+     * {@code [debug]} then logged at {@code DEBUG} level.</li>
+     * <li>logged by a <a href="http://slf4j.org">SLF4J</a> 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.").</li>
+     * </ul>
+     * Example log-message: "[ADB] Cannot read version codes of " is logged by
+     * logger: {@code appium.service.adb} at level {@code INFO}.
+     * <br>
+     * Example log-message: "[debug] [XCUITest] Xcode version set to 'x.y.z' "
+     * is logged by logger {@code appium.service.xcuitest} at level
+     * {@code DEBUG}.
+     * <br>
+     * 
+     * @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.
+     * 
+     * <p>Use this method only if you want a behavior that differentiates from the
+     * default behavior as enabled by method
+     * {@link #enableDefaultSlf4jLoggingOfOutputData()}.
+     * 
+     * <p>NOTE: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method.
+     * 
+     * <p>implementation detail:
+     * <ul>
+     * <li>if log message begins with {@code [debug]} then log level is set to
+     * {@code DEBUG}, otherwise log level is {@code INFO}.</li>
+     * <li>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.</li>
+     * </ul>
+     * Example log-message: "[ADB] Cannot read version codes of " is logged by
+     * {@code appium.service.adb} at level {@code INFO} <br>
+     * Example log-message: "[debug] [XCUITest] Xcode version set to 'x.y.z' "
+     * is logged by {@code appium.service.xcuitest} at level {@code DEBUG}
+     * <br>
+     * 
+     * @param slf4jLogMessageConsumer
+     *            BiConsumer block to be executed when a log message is
+     *            available.
+     */
+    public void addSlf4jLogMessageConsumer(BiConsumer<String, Slf4jLogMessageContext> 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.
+     * 
+     * <p>NOTE: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method.
+     * 
+     * <p>If the Consumer fails and throws an exception the exception is logged (at
+     * WARN level) and execution continues.
+     * <br>
+     * 
+     * @param consumer
+     *            Consumer block to be executed when a log message is available.
+     * 
+     */
+    public void addLogMessageConsumer(Consumer<String> 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);
+                }
+            }
+        });
+    }
 }

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();
+    }
+}

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());
+    }
+}

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<String> 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();