HADOOP-7705

git-svn-id: https://svn.apache.org/repos/asf/hadoop/common/trunk@1183292 13f79535-47bb-0310-9956-ffa450edef68

hadoop-common-project/hadoop-common/CHANGES.txt

@@ -475,6 +475,9 @@ Release 0.23.0 - Unreleased
     HADOOP-7709. Running a set of methods in a Single Test Class. 
     (Jonathan Eagles via mahadev)
 
+    HADOOP-7705. Add a log4j back end that can push out JSON data,
+    one per line. (stevel)
+
   OPTIMIZATIONS
   
     HADOOP-7333. Performance improvement in PureJavaCrc32. (Eric Caspole

hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/log/Log4Json.java

@@ -0,0 +1,262 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+
+package org.apache.hadoop.log;
+
+import org.apache.log4j.Layout;
+import org.apache.log4j.helpers.ISO8601DateFormat;
+import org.apache.log4j.spi.LoggingEvent;
+import org.apache.log4j.spi.ThrowableInformation;
+import org.codehaus.jackson.JsonFactory;
+import org.codehaus.jackson.JsonGenerator;
+import org.codehaus.jackson.JsonNode;
+import org.codehaus.jackson.map.MappingJsonFactory;
+import org.codehaus.jackson.map.ObjectMapper;
+import org.codehaus.jackson.node.ContainerNode;
+
+import java.io.IOException;
+import java.io.StringWriter;
+import java.io.Writer;
+import java.text.DateFormat;
+import java.util.Date;
+
+/**
+ * This offers a log layout for JSON, with some test entry points. It's purpose is
+ * to allow Log4J to generate events that are easy for other programs to parse, but which are somewhat
+ * human-readable.
+ *
+ * Some features.
+ *
+ * <ol>
+ *     <li>Every event is a standalone JSON clause</li>
+ *     <li>Time is published as a time_t event since 1/1/1970
+ *      -this is the fastest to generate.</li>
+ *     <li>An ISO date is generated, but this is cached and will only be accurate to within a second</li>
+ *     <li>the stack trace is included as an array</li>
+ * </ol>
+ *
+ * A simple log event will resemble the following
+ * <pre>
+ *     {"name":"test","time":1318429136789,"date":"2011-10-12 15:18:56,789","level":"INFO","thread":"main","message":"test message"}
+ * </pre>
+ *
+ * An event with an error will contain data similar to that below (which has been reformatted to be multi-line).
+ *
+ * <pre>
+ *     {
+ *     "name":"testException",
+ *     "time":1318429136789,
+ *     "date":"2011-10-12 15:18:56,789",
+ *     "level":"INFO",
+ *     "thread":"quoted\"",
+ *     "message":"new line\n and {}",
+ *     "exceptionclass":"java.net.NoRouteToHostException",
+ *     "stack":[
+ *         "java.net.NoRouteToHostException: that box caught fire 3 years ago",
+ *         "\tat org.apache.hadoop.log.TestLog4Json.testException(TestLog4Json.java:49)",
+ *         "\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)",
+ *         "\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)",
+ *         "\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)",
+ *         "\tat java.lang.reflect.Method.invoke(Method.java:597)",
+ *         "\tat junit.framework.TestCase.runTest(TestCase.java:168)",
+ *         "\tat junit.framework.TestCase.runBare(TestCase.java:134)",
+ *         "\tat junit.framework.TestResult$1.protect(TestResult.java:110)",
+ *         "\tat junit.framework.TestResult.runProtected(TestResult.java:128)",
+ *         "\tat junit.framework.TestResult.run(TestResult.java:113)",
+ *         "\tat junit.framework.TestCase.run(TestCase.java:124)",
+ *         "\tat junit.framework.TestSuite.runTest(TestSuite.java:232)",
+ *         "\tat junit.framework.TestSuite.run(TestSuite.java:227)",
+ *         "\tat org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83)",
+ *         "\tat org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:59)",
+ *         "\tat org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:120)",
+ *         "\tat org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:145)",
+ *         "\tat org.apache.maven.surefire.Surefire.run(Surefire.java:104)",
+ *         "\tat sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)",
+ *         "\tat sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)",
+ *         "\tat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)",
+ *         "\tat java.lang.reflect.Method.invoke(Method.java:597)",
+ *         "\tat org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:290)",
+ *         "\tat org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1017)"
+ *         ]
+ *     }
+ * </pre>
+ */
+public class Log4Json extends Layout {
+
+  /**
+   * Jackson factories are thread safe when constructing parsers and generators.
+   * They are not thread safe in configure methods; if there is to be any
+   * configuration it must be done in a static intializer block.
+   */
+  private static final JsonFactory factory = new MappingJsonFactory();
+  public static final String DATE = "date";
+  public static final String EXCEPTION_CLASS = "exceptionclass";
+  public static final String LEVEL = "level";
+  public static final String MESSAGE = "message";
+  public static final String NAME = "name";
+  public static final String STACK = "stack";
+  public static final String THREAD = "thread";
+  public static final String TIME = "time";
+  public static final String JSON_TYPE = "application/json";
+
+  private final DateFormat dateFormat;
+
+  public Log4Json() {
+    dateFormat = new ISO8601DateFormat();
+  }
+
+
+  /**
+   * @return the mime type of JSON
+   */
+  @Override
+  public String getContentType() {
+    return JSON_TYPE;
+  }
+
+  @Override
+  public String format(LoggingEvent event) {
+    try {
+      return toJson(event);
+    } catch (IOException e) {
+      //this really should not happen, and rather than throw an exception
+      //which may hide the real problem, the log class is printed
+      //in JSON format. The classname is used to ensure valid JSON is 
+      //returned without playing escaping games
+      return "{ \"logfailure\":\"" + e.getClass().toString() + "\"}";
+    }
+  }
+
+  /**
+   * Convert an event to JSON
+   *
+   * @param event the event -must not be null
+   * @return a string value
+   * @throws IOException on problems generating the JSON
+   */
+  public String toJson(LoggingEvent event) throws IOException {
+    StringWriter writer = new StringWriter();
+    toJson(writer, event);
+    return writer.toString();
+  }
+
+  /**
+   * Convert an event to JSON
+   *
+   * @param writer the destination writer
+   * @param event the event -must not be null
+   * @return the writer
+   * @throws IOException on problems generating the JSON
+   */
+  public Writer toJson(final Writer writer, final LoggingEvent event)
+      throws IOException {
+    ThrowableInformation ti = event.getThrowableInformation();
+    toJson(writer,
+           event.getLoggerName(),
+           event.getTimeStamp(),
+           event.getLevel().toString(),
+           event.getThreadName(),
+           event.getRenderedMessage(),
+           ti);
+    return writer;
+  }
+
+  /**
+   * Build a JSON entry from the parameters. This is public for testing.
+   *
+   * @param writer destination
+   * @param loggerName logger name
+   * @param timeStamp time_t value
+   * @param level level string
+   * @param threadName name of the thread
+   * @param message rendered message
+   * @param ti nullable thrown information
+   * @return the writer
+   * @throws IOException on any problem
+   */
+  public Writer toJson(final Writer writer,
+                       final String loggerName,
+                       final long timeStamp,
+                       final String level,
+                       final String threadName,
+                       final String message,
+                       final ThrowableInformation ti) throws IOException {
+    JsonGenerator json = factory.createJsonGenerator(writer);
+    json.writeStartObject();
+    json.writeStringField(NAME, loggerName);
+    json.writeNumberField(TIME, timeStamp);
+    Date date = new Date(timeStamp);
+    json.writeStringField(DATE, dateFormat.format(date));
+    json.writeStringField(LEVEL, level);
+    json.writeStringField(THREAD, threadName);
+    json.writeStringField(MESSAGE, message);
+    if (ti != null) {
+      //there is some throwable info, but if the log event has been sent over the wire,
+      //there may not be a throwable inside it, just a summary.
+      Throwable thrown = ti.getThrowable();
+      String eclass = (thrown != null) ?
+          thrown.getClass().getName()
+          : "";
+      json.writeStringField(EXCEPTION_CLASS, eclass);
+      String[] stackTrace = ti.getThrowableStrRep();
+      json.writeArrayFieldStart(STACK);
+      for (String row : stackTrace) {
+        json.writeString(row);
+      }
+      json.writeEndArray();
+    }
+    json.writeEndObject();
+    json.flush();
+    json.close();
+    return writer;
+  }
+
+  /**
+   * This appender does not ignore throwables
+   *
+   * @return false, always
+   */
+  @Override
+  public boolean ignoresThrowable() {
+    return false;
+  }
+
+  /**
+   * Do nothing
+   */
+  @Override
+  public void activateOptions() {
+  }
+
+  /**
+   * For use in tests
+   *
+   * @param json incoming JSON to parse
+   * @return a node tree
+   * @throws IOException on any parsing problems
+   */
+  public static ContainerNode parse(String json) throws IOException {
+    ObjectMapper mapper = new ObjectMapper(factory);
+    JsonNode jsonNode = mapper.readTree(json);
+    if (!(jsonNode instanceof ContainerNode)) {
+      throw new IOException("Wrong JSON data: " + json);
+    }
+    return (ContainerNode) jsonNode;
+  }
+}

hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/log/TestLog4Json.java

@@ -0,0 +1,270 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.log;
+
+import junit.framework.TestCase;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.apache.log4j.Appender;
+import org.apache.log4j.Category;
+import org.apache.log4j.Level;
+import org.apache.log4j.Logger;
+import org.apache.log4j.WriterAppender;
+import org.apache.log4j.spi.HierarchyEventListener;
+import org.apache.log4j.spi.LoggerFactory;
+import org.apache.log4j.spi.LoggerRepository;
+import org.apache.log4j.spi.ThrowableInformation;
+import org.codehaus.jackson.JsonFactory;
+import org.codehaus.jackson.JsonNode;
+import org.codehaus.jackson.map.MappingJsonFactory;
+import org.codehaus.jackson.node.ContainerNode;
+import org.junit.Test;
+
+import java.io.IOException;
+import java.io.StringWriter;
+import java.io.Writer;
+import java.net.NoRouteToHostException;
+import java.util.Enumeration;
+import java.util.Vector;
+
+public class TestLog4Json extends TestCase {
+
+  private static final Log LOG = LogFactory.getLog(TestLog4Json.class);
+  private static final JsonFactory factory = new MappingJsonFactory();
+
+  @Test
+  public void testConstruction() throws Throwable {
+    Log4Json l4j = new Log4Json();
+    String outcome = l4j.toJson(new StringWriter(),
+        "name", 0, "DEBUG", "thread1",
+        "hello, world", null).toString();
+    println("testConstruction", outcome);
+  }
+
+  @Test
+  public void testException() throws Throwable {
+    Exception e =
+        new NoRouteToHostException("that box caught fire 3 years ago");
+    ThrowableInformation ti = new ThrowableInformation(e);
+    Log4Json l4j = new Log4Json();
+    long timeStamp = System.currentTimeMillis();
+    String outcome = l4j.toJson(new StringWriter(),
+        "testException",
+        timeStamp,
+        "INFO",
+        "quoted\"",
+        "new line\n and {}",
+        ti)
+        .toString();
+    println("testException", outcome);
+  }
+
+  @Test
+  public void testNestedException() throws Throwable {
+    Exception e =
+        new NoRouteToHostException("that box caught fire 3 years ago");
+    Exception ioe = new IOException("Datacenter problems", e);
+    ThrowableInformation ti = new ThrowableInformation(ioe);
+    Log4Json l4j = new Log4Json();
+    long timeStamp = System.currentTimeMillis();
+    String outcome = l4j.toJson(new StringWriter(),
+        "testNestedException",
+        timeStamp,
+        "INFO",
+        "quoted\"",
+        "new line\n and {}",
+        ti)
+        .toString();
+    println("testNestedException", outcome);
+    ContainerNode rootNode = Log4Json.parse(outcome);
+    assertEntryEquals(rootNode, Log4Json.LEVEL, "INFO");
+    assertEntryEquals(rootNode, Log4Json.NAME, "testNestedException");
+    assertEntryEquals(rootNode, Log4Json.TIME, timeStamp);
+    assertEntryEquals(rootNode, Log4Json.EXCEPTION_CLASS,
+        ioe.getClass().getName());
+    JsonNode node = assertNodeContains(rootNode, Log4Json.STACK);
+    assertTrue("Not an array: " + node, node.isArray());
+    node = assertNodeContains(rootNode, Log4Json.DATE);
+    assertTrue("Not a string: " + node, node.isTextual());
+    //rather than try and make assertions about the format of the text
+    //message equalling another ISO date, this test asserts that the hypen
+    //and colon characters are in the string.
+    String dateText = node.getTextValue();
+    assertTrue("No '-' in " + dateText, dateText.contains("-"));
+    assertTrue("No '-' in " + dateText, dateText.contains(":"));
+
+  }
+
+
+  /**
+   * Create a log instance and and log to it
+   * @throws Throwable if it all goes wrong
+   */
+  @Test
+  public void testLog() throws Throwable {
+    String message = "test message";
+    Throwable throwable = null;
+    String json = logOut(message, throwable);
+    println("testLog", json);
+  }
+
+  /**
+   * Create a log instance and and log to it
+   * @throws Throwable if it all goes wrong
+   */
+  @Test
+  public void testLogExceptions() throws Throwable {
+    String message = "test message";
+    Throwable inner = new IOException("Directory / not found");
+    Throwable throwable = new IOException("startup failure", inner);
+    String json = logOut(message, throwable);
+    println("testLogExceptions", json);
+  }
+
+
+  void assertEntryEquals(ContainerNode rootNode, String key, String value) {
+    JsonNode node = assertNodeContains(rootNode, key);
+    assertEquals(value, node.getTextValue());
+  }
+
+  private JsonNode assertNodeContains(ContainerNode rootNode, String key) {
+    JsonNode node = rootNode.get(key);
+    if (node == null) {
+      fail("No entry of name \"" + key + "\" found in " + rootNode.toString());
+    }
+    return node;
+  }
+
+  void assertEntryEquals(ContainerNode rootNode, String key, long value) {
+    JsonNode node = assertNodeContains(rootNode, key);
+    assertEquals(value, node.getNumberValue());
+  }
+
+  /**
+   * Print out what's going on. The logging APIs aren't used and the text
+   * delimited for more details
+   *
+   * @param name name of operation
+   * @param text text to print
+   */
+  private void println(String name, String text) {
+    System.out.println(name + ": #" + text + "#");
+  }
+
+  private String logOut(String message, Throwable throwable) {
+    StringWriter writer = new StringWriter();
+    Logger logger = createLogger(writer);
+    logger.info(message, throwable);
+    //remove and close the appender
+    logger.removeAllAppenders();
+    return writer.toString();
+  }
+
+  public Logger createLogger(Writer writer) {
+    TestLoggerRepository repo = new TestLoggerRepository();
+    Logger logger = repo.getLogger("test");
+    Log4Json layout = new Log4Json();
+    WriterAppender appender = new WriterAppender(layout, writer);
+    logger.addAppender(appender);
+    return logger;
+  }
+
+  /**
+   * This test logger avoids integrating with the main runtimes Logger hierarchy
+   * in ways the reader does not want to know.
+   */
+  private static class TestLogger extends Logger {
+    private TestLogger(String name, LoggerRepository repo) {
+      super(name);
+      repository = repo;
+      setLevel(Level.INFO);
+    }
+
+  }
+
+  public static class TestLoggerRepository implements LoggerRepository {
+    @Override
+    public void addHierarchyEventListener(HierarchyEventListener listener) {
+    }
+
+    @Override
+    public boolean isDisabled(int level) {
+      return false;
+    }
+
+    @Override
+    public void setThreshold(Level level) {
+    }
+
+    @Override
+    public void setThreshold(String val) {
+    }
+
+    @Override
+    public void emitNoAppenderWarning(Category cat) {
+    }
+
+    @Override
+    public Level getThreshold() {
+      return Level.ALL;
+    }
+
+    @Override
+    public Logger getLogger(String name) {
+      return new TestLogger(name, this);
+    }
+
+    @Override
+    public Logger getLogger(String name, LoggerFactory factory) {
+      return new TestLogger(name, this);
+    }
+
+    @Override
+    public Logger getRootLogger() {
+      return new TestLogger("root", this);
+    }
+
+    @Override
+    public Logger exists(String name) {
+      return null;
+    }
+
+    @Override
+    public void shutdown() {
+    }
+
+    @Override
+    public Enumeration getCurrentLoggers() {
+      return new Vector().elements();
+    }
+
+    @Override
+    public Enumeration getCurrentCategories() {
+      return new Vector().elements();
+    }
+
+    @Override
+    public void fireAddAppenderEvent(Category logger, Appender appender) {
+    }
+
+    @Override
+    public void resetConfiguration() {
+    }
+  }
+}