Add MessageParsingMDCLayout to parse unstructured log4j messages into…

… MDC properties to control formatting.

README.md

@@ -74,3 +74,28 @@ The mdc property name can be something other than the header name by using `head
 Then, in log4j.properties (or elsewhere):
 
     log4j.appender.file.layout.ConversionPattern=%-5p - %d{yyyy-MM-dd HH:mm:ss.SSS}; %C; request_id:%X{request_id} %m\n
+
+## MessageParsingMDCLayout
+
+This library also includes a delegating log4j layout that uses regex to
+parse a formatted message into MDC properties for structured logging.
+
+In practice this layout was developed to give structure to Solr logs so that
+metadata like hits, query time and status can be sent as separate fields in
+a JSON-formatted output suitable for integration with LogStash.
+
+Example configuration:
+
+```
+#- size rotation with log cleanup.
+log4j.appender.file=org.apache.log4j.RollingFileAppender
+log4j.appender.file.MaxFileSize=4MB
+log4j.appender.file.MaxBackupIndex=9
+
+#- File to log to and log format
+log4j.appender.file.File=${solr.log}/solr.log
+log4j.appender.file.layout=com.fool.log4j.layout.MessageParsingMDCLayout
+log4j.appender.file.layout.regex=^\\[([^\\]]+)\\] webapp=([\\S]+) path=([\\S]+) params=([\\S]+) (?:hits=([\\d]+) )?status=([\\d]+) QTime=([\\d]+).*$
+log4j.appender.file.layout.fieldNames=core, webapp, path, params, hits, status, qtime
+log4j.appender.file.layout.layout=net.logstash.log4j.JSONEventLayoutV1
+```

src/main/java/com/fool/log4j/layout/MessageParsingMDCLayout.java

@@ -0,0 +1,113 @@
+package com.fool.log4j.layout;
+
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+
+import org.apache.log4j.Layout;
+import org.apache.log4j.helpers.LogLog;
+import org.apache.log4j.spi.LoggingEvent;
+
+public class MessageParsingMDCLayout extends Layout {
+	private Layout layout;
+	private String regex;
+	private String fieldNames;
+
+	private List<String> fieldList = new ArrayList<String>();
+	private Pattern pattern;
+
+	@Override
+	public void activateOptions() {
+		if (layout == null) {
+			throw new RuntimeException(this.getClass().getSimpleName() + " requires layout to delegate to.");
+		}
+		if (regex == null) {
+			throw new RuntimeException(this.getClass().getSimpleName() + " requires regex.");
+		}
+		if (fieldNames == null) {
+			throw new RuntimeException(this.getClass().getSimpleName() + " requires fieldNames.");
+		}
+
+		this.pattern = Pattern.compile(regex);
+		for (String s : fieldNames.split(",")) {
+			fieldList.add(s.trim());
+		}
+	}
+
+	public void setLayout(Layout layout) {
+		this.layout = layout;
+	}
+
+	@Override
+	public String format(LoggingEvent event) {
+		String message = event.getRenderedMessage();
+
+		Matcher matcher = pattern.matcher(message);
+		if (!matcher.matches()) {
+			return layout.format(event);
+		}
+
+		if (matcher.groupCount() > fieldList.size()) {
+			LogLog.warn("Captured " + (matcher.groupCount()) + " values but only have " + fieldList.size() + " fields.");
+			return layout.format(event);
+		}
+
+		Map<String, Object> properties = new HashMap<String, Object>(event.getProperties());
+
+		for(int i=1; i<=matcher.groupCount(); i++) {
+			Object value = coerce(matcher.group(i));
+			if (value == null) continue;
+			properties.put(fieldList.get(i-1), value);
+		}
+
+		event = new LoggingEvent(
+				event.fqnOfCategoryClass,
+				event.getLogger(),
+				event.timeStamp,
+				event.getLevel(), 
+				event.getMessage(),
+				event.getThreadName(),
+				event.getThrowableInformation(),
+				event.getNDC(),
+				event.getLocationInformation(),
+				properties);
+
+		return layout.format(event);	
+	}
+
+	public Object coerce(String value) {
+		if (value == null || value.equals("")) {
+			return null;
+		}
+
+		try {
+			return Long.parseLong(value);
+		} catch (NumberFormatException ex) {
+		}
+
+		try {
+			return Double.parseDouble(value);
+		} catch (NumberFormatException ex) {
+		}
+
+		return value;
+	}
+
+	@Override
+	public boolean ignoresThrowable() {
+		return layout.ignoresThrowable();
+	}
+
+	public void setRegex(String regex) {
+		this.regex = regex;
+	}
+
+	public void setFieldNames(String fieldNames) {
+		this.fieldNames = fieldNames;
+	}
+
+}
+

src/test/java/com/fool/log4j/Layout/MessageParsingMDCLayoutTests.java

@@ -0,0 +1,129 @@
+package com.fool.log4j.Layout;
+
+import java.util.HashMap;
+import java.util.Map;
+
+import org.apache.log4j.Layout;
+import org.apache.log4j.Level;
+import org.apache.log4j.spi.LoggingEvent;
+
+import com.fool.log4j.layout.MessageParsingMDCLayout;
+
+import junit.framework.TestCase;
+
+public class MessageParsingMDCLayoutTests extends TestCase {
+	private MessageParsingMDCLayout layout;
+	private Map<String, Object> capturedProperties;
+
+	@Override
+	protected void setUp() throws Exception {
+		super.setUp();
+		layout = new MessageParsingMDCLayout();
+		layout.setLayout(new LayoutStub());
+	}
+
+	public void testAddsProperties() throws Exception {
+		layout.setRegex("\\[([^\\]]+)\\] path=([\\S]+)");
+		layout.setFieldNames("log_id, path");
+		layout.activateOptions();
+		String message = "[ID1] path=/foo/bar";
+
+		layout.format(new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null));
+
+		assertNotNull("capturedProperties", capturedProperties);
+		assertEquals("log_id", "ID1", capturedProperties.get("log_id"));
+		assertEquals("path", "/foo/bar", capturedProperties.get("path"));
+	}
+
+	public void testOptionalCaptureGroupWithoutProperty() throws Exception {
+		layout.setRegex("(?:hits=([\\d]+) )?status=([\\d]+)");
+		layout.setFieldNames("hits, status");
+		layout.activateOptions();
+		String message = "status=0";
+
+		layout.format(new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null));
+
+		assertNotNull("capturedProperties", capturedProperties);
+		assertFalse("hits is not present", capturedProperties.containsKey("hits"));
+		assertEquals("status", 0L, capturedProperties.get("status"));
+	}
+
+	public void testOptionalCaptureGroupWithProperty() throws Exception {
+		layout.setRegex("(?:hits=([\\d]+) )?status=([\\d]+)");
+		layout.setFieldNames("hits, status");
+		layout.activateOptions();
+		String message = "hits=987 status=0";
+
+		layout.format(new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null));
+
+		assertNotNull("capturedProperties", capturedProperties);
+		assertEquals("hits", 987L, capturedProperties.get("hits"));
+		assertEquals("status", 0L, capturedProperties.get("status"));
+	}
+
+	public void testRemovesProperties() throws Exception {
+		layout.setRegex("\\[([^\\]]+)\\] path=([^s]+)");
+		layout.setFieldNames("log_id, path");
+		layout.activateOptions();
+		String message = "[ID1] path=/foo/bar";
+		LoggingEvent event = new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null);
+
+		layout.format(event);
+
+		assertFalse("Should remove property upon completion", event.getProperties().containsKey("log_id"));
+	}
+
+	public void testNotEnoughFieldNames() throws Exception {
+		layout.setRegex("\\[([^\\]]+)\\] path=([^s]+)");
+		layout.setFieldNames("log_id");
+		layout.activateOptions();
+		String message = "[ID1] path=/foo/bar";
+		LoggingEvent event = new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null);
+
+		layout.format(event);
+
+		assertFalse("Should remove property upon completion", event.getProperties().containsKey("log_id"));
+	}
+
+	public void testCoerceToLong() throws Exception {
+		layout.setRegex("^.* hits=([\\d]+) .*$");
+		layout.setFieldNames("hits");
+		layout.activateOptions();
+		String message = "[ID1] hits=42342342353432454 path=/foo/bar";
+
+		layout.format(new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null));
+
+		assertNotNull("capturedProperties", capturedProperties);
+		assertEquals("hits", 42342342353432454L, capturedProperties.get("hits"));
+	}
+
+	public void testCoerceToDouble() throws Exception {
+		layout.setRegex("^.* time=([\\d.]+) .*$");
+		layout.setFieldNames("time");
+		layout.activateOptions();
+		String message = "[ID1] time=42.454 path=/foo/bar";
+
+		layout.format(new LoggingEvent("fqn", null, System.currentTimeMillis(), Level.INFO, message, "thread", null, "ndc", null, null));
+
+		assertNotNull("capturedProperties", capturedProperties);
+		assertEquals("time", 42.454D, capturedProperties.get("time"));
+	}
+
+	class LayoutStub extends Layout {
+		@SuppressWarnings("unchecked")
+		@Override
+		public String format(LoggingEvent event) {
+			capturedProperties = new HashMap<String, Object>(event.getProperties());
+			return "a message";
+		}
+
+		@Override
+		public void activateOptions() {
+		}
+
+		@Override
+		public boolean ignoresThrowable() {
+			return false;
+		}
+	}
+}