Add SLF4J logging support for Appium local service

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,6 +17,8 @@
 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.collect.ImmutableList;
 import com.google.common.collect.ImmutableMap;
@@ -26,6 +28,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 +40,19 @@
 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 final File nodeJSExec;
     private final ImmutableList<String> nodeJSArgs;
     private final ImmutableMap<String, String> nodeJSEnvironment;
@@ -219,4 +232,127 @@ 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).</br>
+     * </br>
+     * NOTE1: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method. </br>
+     * NOTE2: it is required that {@link --log-timestamp} server flag is
+     * {@link false}. </br>
+     * </br>
+     * By default log messages are:
+     * <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> </br>
+     * 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>
+     * </br>
+     * 
+     * @see #addSlf4jLogMessageConsumer(BiConsumer)
+     */
+    public void enableDefaultSlf4jLoggingOfOutputData() {
+        addSlf4jLogMessageConsumer((logMessage, ctx) -> {
+            if (ctx.level().equals(DEBUG)) {
+                ctx.logger().debug(logMessage);
+            } else {
+                ctx.logger().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.</br>
+     * </br>
+     * Use this method only if you want a behavior that differentiates from the
+     * default behavior as enabled by method
+     * {@link #enableDefaultSlf4jLoggingOfOutputData()}. </br>
+     * </br>
+     * NOTE: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method. </br>
+     * </br>
+     * implementation detail:
+     * <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> </br>
+     * 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}
+     * 
+     * @param slf4jLogMessageConsumer
+     *            BiConsumer block to be executed when a log message is
+     *            available.
+     */
+    public void addSlf4jLogMessageConsumer(
+            BiConsumer<String, Slf4jLogMessageContext> slf4jLogMessageConsumer) {
+        addLogMessageConsumer(logMessage -> {
+            slf4jLogMessageConsumer.accept(logMessage, parseSlf4jContextFromLogMessage(logMessage));
+        });
+    }
+
+    static Slf4jLogMessageContext parseSlf4jContextFromLogMessage(String logMessage) {
+        Matcher m = LOGGER_CONTEXT_PATTERN.matcher(logMessage);
+        String loggerName = "appium.service";
+        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. </br>
+     * </br>
+     * NOTE: You might want to call method {@link #clearOutPutStreams()} before
+     * calling this method. </br>
+     * </br>
+     * 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<String> consumer) {
+        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,44 @@
+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. 
+ * 
+ * @see {@link AppiumDriverLocalService#addSlf4jLogMessageConsumer(java.util.function.BiConsumer)}
+ * 
+ */
+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);
+	}
+
+	/**
+	 * @return {@link Logger} instance associated with this context.
+	 * 
+	 */
+	public Logger logger() {
+		return logger;
+	}
+
+	/**
+	 * @return {@link Level} for log message associated with this context.
+	 */
+	public Level level() {
+		return level;
+	}
+
+	/**
+	 * @return name of {@link Logger} associated with this context.
+	 */
+	public String name() {
+		return logger.getName();
+	}
+
+}

src/test/java/io/appium/java_client/service/local/AppiumDriverLocalServiceTest.java

@@ -0,0 +1,32 @@
+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.name());
+		assertEquals(expectedLevel, ctx.level());
+		assertEquals(getLogger(expectedLoggerName), ctx.logger());
+	}
+}

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