#87 Grouping stack traces into single log statements for sub-processes

src/main/java/com/jcabi/log/VerboseProcess.java

@@ -403,22 +403,50 @@ private static void close(final Closeable res) {
      * Stream monitor.
      */
     private static final class Monitor implements Callable<Void> {
+
+        /**
+         * Maximum number of log lines for a stack trace. Set to 1000
+         * to avoid storing too many lines in memory before flushing.
+         */
+        private static final int MAX_STACK_LENGTH = 1000;
+
+        /**
+         * Format string for log statements.
+         */
+        private static final String LOG_FORMAT = ">> %s";
+
+        /**
+         * Empty String.
+         */
+        private static final String EMPTY_STRING = "";
+
+        /**
+         * Newline string.
+         */
+        private static final String NEW_LINE = System.getProperty(
+            "line.separator"
+        );
+
         /**
          * Stream to read.
          */
         private final transient InputStream input;
+
         /**
          * Latch to count down when done.
          */
         private final transient CountDownLatch done;
+
         /**
          * Buffer to save output.
          */
         private final transient OutputStream output;
+
         /**
          * Log level.
          */
         private final transient Level level;
+
         /**
          * Ctor.
          * @param inp Stream to monitor
@@ -434,38 +462,20 @@ private static final class Monitor implements Callable<Void> {
             this.output = out;
             this.level = lvl;
         }
+
         @Override
         public Void call() throws Exception {
             final BufferedReader reader = new BufferedReader(
                 Channels.newReader(
-                    Channels.newChannel(this.input),
-                    VerboseProcess.UTF_8
+                    Channels.newChannel(this.input), VerboseProcess.UTF_8
                 )
             );
             try {
                 final BufferedWriter writer = new BufferedWriter(
                     new OutputStreamWriter(this.output, VerboseProcess.UTF_8)
                 );
                 try {
-                    while (true) {
-                        if (Thread.interrupted()) {
-                            Logger.debug(
-                                VerboseProcess.class,
-                                "explicitly interrupting read from buffer"
-                            );
-                            break;
-                        }
-                        final String line = reader.readLine();
-                        if (line == null) {
-                            break;
-                        }
-                        Logger.log(
-                            this.level, VerboseProcess.class,
-                            ">> %s", line
-                        );
-                        writer.write(line);
-                        writer.newLine();
-                    }
+                    this.logFromReader(reader, writer);
                 } catch (final ClosedByInterruptException ex) {
                     Thread.interrupted();
                     Logger.debug(
@@ -487,6 +497,90 @@ public Void call() throws Exception {
             }
             return null;
         }
+
+        /**
+         * Logs supplied BufferedReader to Logger and supplied Writer.
+         * @param reader Reader to use
+         * @param writer Writer to use
+         * @throws IOException writer could throw this
+         */
+        private void logFromReader(final BufferedReader reader,
+                final BufferedWriter writer) throws IOException {
+            final StringBuilder builder = new StringBuilder();
+            String previous = EMPTY_STRING;
+            int count = 0;
+            while (true) {
+                if (Thread.interrupted()) {
+                    Logger.debug(
+                        VerboseProcess.class,
+                        "explicitly interrupting read from buffer"
+                    );
+                    break;
+                }
+                if (!previous.isEmpty()) {
+                    appendLine(previous, builder);
+                    previous = EMPTY_STRING;
+                }
+                final String line = reader.readLine();
+                if (line == null) {
+                    logAndClear(writer, this.level, builder);
+                    break;
+                }
+                if (shouldAppend(line)
+                        && count < MAX_STACK_LENGTH) {
+                    appendLine(line, builder);
+                    ++count;
+                } else {
+                    if (builder.length() > 0) {
+                        logAndClear(writer, this.level, builder);
+                    }
+                    count = 1;
+                    previous = line;
+                }
+            }
+        }
+
+        /**
+         * Appends a line and a newline character to the builder.
+         * @param line String to append
+         * @param builder StringBuilder with log statement
+         */
+        private static void appendLine(final String line,
+                final StringBuilder builder) {
+            builder.append(line);
+            builder.append(NEW_LINE);
+        }
+
+        /**
+         * Logs StringBuilder to Logger and supplied Writer then clears out
+         * the builder.
+         * @param writer Writer to use
+         * @param level Level to log at
+         * @param builder StringBuilder with log statement
+         * @throws IOException writer could throw this
+         */
+        private static void logAndClear(final BufferedWriter writer,
+                final Level level, final StringBuilder builder)
+                throws IOException {
+            if (builder.length() > 0) {
+                final String text = builder.toString();
+                Logger.log(level, VerboseProcess.class, LOG_FORMAT, text);
+                writer.write(text);
+            }
+            builder.setLength(0);
+        }
+
+        /**
+         * Checks if line is part of a stack trace and should be appended.
+         * @param input String to check
+         * @return Result, true or false
+         */
+        private static boolean shouldAppend(final String input) {
+            final String trimmed = input.trim();
+            return trimmed.startsWith("at ")
+                || trimmed.startsWith("Caused by")
+                || trimmed.startsWith("... ");
+        }
     }
 
     /**

src/test/java/com/jcabi/log/SupplierLoggerTest.java

@@ -32,6 +32,7 @@
 import org.apache.log4j.Level;
 import org.hamcrest.MatcherAssert;
 import org.hamcrest.Matchers;
+import org.junit.BeforeClass;
 import org.junit.Test;
 
 /**
@@ -43,6 +44,18 @@
 @SuppressWarnings("PMD.MoreThanOneLogger")
 public final class SupplierLoggerTest {
 
+    /**
+     * Logs before method to avoid timing issue where loggers were
+     * created "during the default configuration phase of the underlying
+     * logging system" and failing tests in Travis CI.
+     */
+    @BeforeClass
+    public static void init() {
+        final org.apache.log4j.Logger logger =
+                org.apache.log4j.Logger.getRootLogger();
+        logger.info("Logging here to avoid timing issue with Travis CI");
+    }
+
     /**
      * SupplierLogger can tell if debug is disabled and the message is not
      * logged enabled.

src/test/java/com/jcabi/log/VerboseProcessExample.java

@@ -0,0 +1,120 @@
+/**
+ * Copyright (c) 2012-2016, jcabi.com
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions
+ * are met: 1) Redistributions of source code must retain the above
+ * copyright notice, this list of conditions and the following
+ * disclaimer. 2) Redistributions in binary form must reproduce the above
+ * copyright notice, this list of conditions and the following
+ * disclaimer in the documentation and/or other materials provided
+ * with the distribution. 3) Neither the name of the jcabi.com nor
+ * the names of its contributors may be used to endorse or promote
+ * products derived from this software without specific prior written
+ * permission.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+ * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT
+ * NOT LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND
+ * FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL
+ * THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT,
+ * INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
+ * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR
+ * SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
+ * STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+ * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED
+ * OF THE POSSIBILITY OF SUCH DAMAGE.
+ */
+package com.jcabi.log;
+
+/**
+ * Example application to help test {@link VerboseProcess}.
+ * @author Dean Clark ([email protected])
+ * @version $Id: 97615996e8472494c4561b6d9d5bca0e7f6992dc $
+ * @since 1.20.1
+ */
+@SuppressWarnings("PMD.DefaultPackage")
+public final class VerboseProcessExample {
+
+    /**
+     * System output line 1.
+     */
+    static final String SYSOUT_1 = "sysout line 1";
+
+    /**
+     * System output line 2.
+     */
+    static final String SYSOUT_2 = "sysout line 2";
+
+    /**
+     * Error output line 1.
+     */
+    static final String SYSERR_1 = "syserr line 1";
+
+    /**
+     * Error output line 2.
+     */
+    static final String SYSERR_2 = "syserr line 2";
+
+    /**
+     * Exception to be thrown and caught.
+     */
+    static final String CAUGHT_ERR_MSG = "throw/catch me";
+
+    /**
+     * Exception to be thrown.
+     */
+    static final String THROWN_ERR_MSG = "just throw me";
+
+    /**
+     * Private constructor. Intentionally empty.
+     */
+    private VerboseProcessExample() { }
+
+    /**
+     * Instantiates instance of this class and calls primary method.
+     * @param args Any args passed to main method
+     */
+    public static void main(final String... args) {
+        final VerboseProcessExample instance = new VerboseProcessExample();
+        instance.doWork();
+    }
+
+    /**
+     * Will log to standard output and error and then intentionally fail with a
+     * stack trace.
+     */
+    @SuppressWarnings("PMD.SystemPrintln")
+    private void doWork() {
+        System.out.println(SYSOUT_1);
+        System.err.println(SYSERR_1);
+        System.out.println(SYSOUT_2);
+        System.err.println(SYSERR_2);
+        catchAndThrow();
+    }
+
+    /**
+     * Call a method which will throw an exception. Then catch and re-throw it.
+     */
+    private static void catchAndThrow() {
+        try {
+            countdownAndThrow(2);
+        } catch (final IllegalStateException ex) {
+            throw new IllegalStateException(THROWN_ERR_MSG, ex);
+        }
+    }
+
+    /**
+     * Recursively loops and then throws an exception.
+     * @param loops Times to loop
+     */
+    private static void countdownAndThrow(final int loops) {
+        if (loops == 0) {
+            throw new IllegalStateException(CAUGHT_ERR_MSG);
+        }
+        countdownAndThrow(loops - 1);
+    }
+
+}