log4j-gctests/src/test/java/org/apache/logging/log4j/gctests/GcFreeLoggingTestUtil.java - logging-log4j2 - Git at Google

 /*
  * 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.logging.log4j.gctests;

 import com.google.monitoring.runtime.instrumentation.AllocationRecorder;
 import com.google.monitoring.runtime.instrumentation.Sampler;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Marker;
 import org.apache.logging.log4j.MarkerManager;
 import org.apache.logging.log4j.ThreadContext;
 import org.apache.logging.log4j.core.util.Constants;
 import org.apache.logging.log4j.message.StringMapMessage;

 import java.io.File;
 import java.net.URL;
 import java.nio.charset.Charset;
 import java.nio.file.Files;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.regex.Pattern;

 import static java.lang.System.getProperty;
 import static org.junit.jupiter.api.Assertions.assertFalse;
 import static org.junit.jupiter.api.Assertions.assertTrue;

 /**
  * Utility methods for the GC-free logging tests.
  */
 public enum GcFreeLoggingTestUtil {;

     public static void executeLogging(final String configurationFile,
                                       final Class<?> testClass) throws Exception {

         System.setProperty("log4j2.enable.threadlocals", "true");
         System.setProperty("log4j2.enable.direct.encoders", "true");
         System.setProperty("log4j2.is.webapp", "false");
         System.setProperty("log4j.configurationFile", configurationFile);

         assertTrue(Constants.ENABLE_THREADLOCALS, "Constants.ENABLE_THREADLOCALS");
         assertTrue(Constants.ENABLE_DIRECT_ENCODERS, "Constants.ENABLE_DIRECT_ENCODERS");
         assertFalse(Constants.IS_WEB_APP, "Constants.IS_WEB_APP");

         final MyCharSeq myCharSeq = new MyCharSeq();
         final Marker testGrandParent = MarkerManager.getMarker("testGrandParent");
         final Marker testParent = MarkerManager.getMarker("testParent").setParents(testGrandParent);
         final Marker test = MarkerManager.getMarker("test").setParents(testParent); // initial creation, value is cached

         // initialize LoggerContext etc.
         // This is not steady-state logging and will allocate objects.
         ThreadContext.put("aKey", "value1");
         ThreadContext.put("key2", "value2");

         final org.apache.logging.log4j.Logger logger = LogManager.getLogger(testClass.getName());
         logger.debug("debug not set");
         logger.fatal(test, "This message is logged to the console");
         logger.error("Sample error message");
         logger.error("Test parameterized message {}", "param");
         logger.error(new StringMapMessage().with("eventId", "Login")); // initialize GelfLayout's messageStringBuilder
         for (int i = 0; i < 256; i++) {
             logger.debug("ensure all ringbuffer slots have been used once"); // allocate MutableLogEvent.messageText
         }
         ThreadContext.remove("aKey");
         ThreadContext.remove("key2");

         // BlockingWaitStrategy uses ReentrantLock which allocates Node objects. Ignore this.
         final String[] exclude = new String[] {
                 "java/util/concurrent/locks/AbstractQueuedSynchronizer$Node", //
                 "com/google/monitoring/runtime/instrumentation/Sampler", //
         };
         final AtomicBoolean samplingEnabled = new AtomicBoolean(true);
         final Sampler sampler = new Sampler() {
             @Override
             public void sampleAllocation(final int count, final String desc, final Object newObj, final long size) {
                 if (!samplingEnabled.get()) {
                     return;
                 }
                 for (int i = 0; i < exclude.length; i++) {
                     if (exclude[i].equals(desc)) {
                         return; // exclude
                     }
                 }
                 System.err.println("I just allocated the object " + newObj +
                         " of type " + desc + " whose size is " + size);
                 if (count != -1) {
                     System.err.println("It's an array of size " + count);
                 }

                 // show a stack trace to see which line caused allocation
                 new RuntimeException().printStackTrace();
             }
         };
         Thread.sleep(500);
         final StringMapMessage mapMessage = new StringMapMessage().with("eventId", "Login");
         AllocationRecorder.addSampler(sampler);

         // now do some steady-state logging

         ThreadContext.put("aKey", "value1");
         ThreadContext.put("key2", "value2");

         final int ITERATIONS = 5;
         for (int i = 0; i < ITERATIONS; i++) {
             logger.error(myCharSeq);
             logger.error(MarkerManager.getMarker("test"), myCharSeq);
             logger.error("Test message");
             logger.error("Test parameterized message {}", "param");
             logger.error("Test parameterized message {}{}", "param", "param2");
             logger.error("Test parameterized message {}{}{}", "param", "param2", "abc");
             logger.error(mapMessage); // LOG4J2-1683
             ThreadContext.remove("aKey");
             ThreadContext.put("aKey", "value1");
         }
         Thread.sleep(50);
         samplingEnabled.set(false); // reliably ignore all allocations from now on
         AllocationRecorder.removeSampler(sampler);
         Thread.sleep(100);
     }

     public static void runTest(final Class<?> cls) throws Exception {
         final String javaHome = getProperty("java.home");
         final String javaBin = javaHome + File.separator + "bin" + File.separator + "java";
         final String classpath = getProperty("java.class.path");
         final String javaagent = "-javaagent:" + agentJar();
         final String usePreciseClock = System.getProperty("log4j2.usePreciseClock");

         final File tempFile = File.createTempFile("allocations", ".txt");
         tempFile.deleteOnExit();
         List<String> command = new ArrayList<>();
         command.add(javaBin);
         command.add(javaagent);
         if (usePreciseClock != null) {
             command.add("-Dlog4j2.usePreciseClock=" + usePreciseClock);
         }
         command.add("-cp");
         command.add(classpath);
         command.add(cls.getName());
         final ProcessBuilder builder = new ProcessBuilder(command);
         builder.redirectError(ProcessBuilder.Redirect.to(tempFile));
         builder.redirectOutput(ProcessBuilder.Redirect.to(tempFile));
         final Process process = builder.start();
         process.waitFor();
         process.exitValue();

         final AtomicInteger lineCounter = new AtomicInteger(0);
         Files.lines(tempFile.toPath(), Charset.defaultCharset()).forEach(line -> {

             // Trim the line.
             line = line.trim();

             // Check the first line.
             final int lineNumber = lineCounter.incrementAndGet();
             if (lineNumber == 1) {
                 final String className = cls.getSimpleName();
                 final String firstLinePattern = String.format(
                         "^FATAL .*\\.%s %s",
                         className,
                         Pattern.quote("[main] value1 {aKey=value1, " +
                                 "key2=value2, prop1=value1, prop2=value2} " +
                                 "This message is logged to the console"));
                 assertTrue(line.matches(firstLinePattern),
                         "pattern mismatch at line 1: " + line);
             }

             // Check the rest of the lines. We are looking for the messages written to System.err
             // in the sampleAllocation() method above in executeLogging().
             else {
                 assertFalse(line.contains(" allocated ") || line.contains(" array "),
                         "(allocated|array) pattern matches at line " + lineNumber + ": " + line);
             }

         });

     }

     private static File agentJar() throws Exception {
         final String name = AllocationRecorder.class.getName();
         final URL url = AllocationRecorder.class.getResource("/" + name.replace('.', '/').concat(".class"));
         if (url == null) {
             throw new IllegalStateException("Could not find url for " + name);
         }
         final String temp = url.toString();
         final URL jarurl = new URL(temp.substring("jar:".length(), temp.indexOf('!')));
         return new File(jarurl.toURI());
     }

     public static class MyCharSeq implements CharSequence {
         final String seq = GcFreeLoggingTestUtil.class.toString();

         @Override
         public int length() {
             return seq.length();
         }

         @Override
         public char charAt(final int index) {
             return seq.charAt(index);
         }

         @Override
         public CharSequence subSequence(final int start, final int end) {
             return seq.subSequence(start, end);
         }

         @Override
         public String toString() {
             System.err.println("TEMP OBJECT CREATED!");
             throw new IllegalStateException("TEMP OBJECT CREATED!");
         }
     }
 }
	/*
	* 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.logging.log4j.gctests;

	import com.google.monitoring.runtime.instrumentation.AllocationRecorder;
	import com.google.monitoring.runtime.instrumentation.Sampler;
	import org.apache.logging.log4j.LogManager;
	import org.apache.logging.log4j.Marker;
	import org.apache.logging.log4j.MarkerManager;
	import org.apache.logging.log4j.ThreadContext;
	import org.apache.logging.log4j.core.util.Constants;
	import org.apache.logging.log4j.message.StringMapMessage;

	import java.io.File;
	import java.net.URL;
	import java.nio.charset.Charset;
	import java.nio.file.Files;
	import java.util.ArrayList;
	import java.util.List;
	import java.util.concurrent.atomic.AtomicBoolean;
	import java.util.concurrent.atomic.AtomicInteger;
	import java.util.regex.Pattern;

	import static java.lang.System.getProperty;
	import static org.junit.jupiter.api.Assertions.assertFalse;
	import static org.junit.jupiter.api.Assertions.assertTrue;

	/**
	* Utility methods for the GC-free logging tests.
	*/
	public enum GcFreeLoggingTestUtil {;

	public static void executeLogging(final String configurationFile,
	final Class<?> testClass) throws Exception {

	System.setProperty("log4j2.enable.threadlocals", "true");
	System.setProperty("log4j2.enable.direct.encoders", "true");
	System.setProperty("log4j2.is.webapp", "false");
	System.setProperty("log4j.configurationFile", configurationFile);

	assertTrue(Constants.ENABLE_THREADLOCALS, "Constants.ENABLE_THREADLOCALS");
	assertTrue(Constants.ENABLE_DIRECT_ENCODERS, "Constants.ENABLE_DIRECT_ENCODERS");
	assertFalse(Constants.IS_WEB_APP, "Constants.IS_WEB_APP");

	final MyCharSeq myCharSeq = new MyCharSeq();
	final Marker testGrandParent = MarkerManager.getMarker("testGrandParent");
	final Marker testParent = MarkerManager.getMarker("testParent").setParents(testGrandParent);
	final Marker test = MarkerManager.getMarker("test").setParents(testParent); // initial creation, value is cached

	// initialize LoggerContext etc.
	// This is not steady-state logging and will allocate objects.
	ThreadContext.put("aKey", "value1");
	ThreadContext.put("key2", "value2");

	final org.apache.logging.log4j.Logger logger = LogManager.getLogger(testClass.getName());
	logger.debug("debug not set");
	logger.fatal(test, "This message is logged to the console");
	logger.error("Sample error message");
	logger.error("Test parameterized message {}", "param");
	logger.error(new StringMapMessage().with("eventId", "Login")); // initialize GelfLayout's messageStringBuilder
	for (int i = 0; i < 256; i++) {
	logger.debug("ensure all ringbuffer slots have been used once"); // allocate MutableLogEvent.messageText
	}
	ThreadContext.remove("aKey");
	ThreadContext.remove("key2");

	// BlockingWaitStrategy uses ReentrantLock which allocates Node objects. Ignore this.
	final String[] exclude = new String[] {
	"java/util/concurrent/locks/AbstractQueuedSynchronizer$Node", //
	"com/google/monitoring/runtime/instrumentation/Sampler", //
	};
	final AtomicBoolean samplingEnabled = new AtomicBoolean(true);
	final Sampler sampler = new Sampler() {
	@Override
	public void sampleAllocation(final int count, final String desc, final Object newObj, final long size) {
	if (!samplingEnabled.get()) {
	return;
	}
	for (int i = 0; i < exclude.length; i++) {
	if (exclude[i].equals(desc)) {
	return; // exclude
	}
	}
	System.err.println("I just allocated the object " + newObj +
	" of type " + desc + " whose size is " + size);
	if (count != -1) {
	System.err.println("It's an array of size " + count);
	}

	// show a stack trace to see which line caused allocation
	new RuntimeException().printStackTrace();
	}
	};
	Thread.sleep(500);
	final StringMapMessage mapMessage = new StringMapMessage().with("eventId", "Login");
	AllocationRecorder.addSampler(sampler);

	// now do some steady-state logging

	ThreadContext.put("aKey", "value1");
	ThreadContext.put("key2", "value2");

	final int ITERATIONS = 5;
	for (int i = 0; i < ITERATIONS; i++) {
	logger.error(myCharSeq);
	logger.error(MarkerManager.getMarker("test"), myCharSeq);
	logger.error("Test message");
	logger.error("Test parameterized message {}", "param");
	logger.error("Test parameterized message {}{}", "param", "param2");
	logger.error("Test parameterized message {}{}{}", "param", "param2", "abc");
	logger.error(mapMessage); // LOG4J2-1683
	ThreadContext.remove("aKey");
	ThreadContext.put("aKey", "value1");
	}
	Thread.sleep(50);
	samplingEnabled.set(false); // reliably ignore all allocations from now on
	AllocationRecorder.removeSampler(sampler);
	Thread.sleep(100);
	}

	public static void runTest(final Class<?> cls) throws Exception {
	final String javaHome = getProperty("java.home");
	final String javaBin = javaHome + File.separator + "bin" + File.separator + "java";
	final String classpath = getProperty("java.class.path");
	final String javaagent = "-javaagent:" + agentJar();
	final String usePreciseClock = System.getProperty("log4j2.usePreciseClock");

	final File tempFile = File.createTempFile("allocations", ".txt");
	tempFile.deleteOnExit();
	List<String> command = new ArrayList<>();
	command.add(javaBin);
	command.add(javaagent);
	if (usePreciseClock != null) {
	command.add("-Dlog4j2.usePreciseClock=" + usePreciseClock);
	}
	command.add("-cp");
	command.add(classpath);
	command.add(cls.getName());
	final ProcessBuilder builder = new ProcessBuilder(command);
	builder.redirectError(ProcessBuilder.Redirect.to(tempFile));
	builder.redirectOutput(ProcessBuilder.Redirect.to(tempFile));
	final Process process = builder.start();
	process.waitFor();
	process.exitValue();

	final AtomicInteger lineCounter = new AtomicInteger(0);
	Files.lines(tempFile.toPath(), Charset.defaultCharset()).forEach(line -> {

	// Trim the line.
	line = line.trim();

	// Check the first line.
	final int lineNumber = lineCounter.incrementAndGet();
	if (lineNumber == 1) {
	final String className = cls.getSimpleName();
	final String firstLinePattern = String.format(
	"^FATAL .*\\.%s %s",
	className,
	Pattern.quote("[main] value1 {aKey=value1, " +
	"key2=value2, prop1=value1, prop2=value2} " +
	"This message is logged to the console"));
	assertTrue(line.matches(firstLinePattern),
	"pattern mismatch at line 1: " + line);
	}

	// Check the rest of the lines. We are looking for the messages written to System.err
	// in the sampleAllocation() method above in executeLogging().
	else {
	assertFalse(line.contains(" allocated ") \|\| line.contains(" array "),
	"(allocated\|array) pattern matches at line " + lineNumber + ": " + line);
	}

	});

	}

	private static File agentJar() throws Exception {
	final String name = AllocationRecorder.class.getName();
	final URL url = AllocationRecorder.class.getResource("/" + name.replace('.', '/').concat(".class"));
	if (url == null) {
	throw new IllegalStateException("Could not find url for " + name);
	}
	final String temp = url.toString();
	final URL jarurl = new URL(temp.substring("jar:".length(), temp.indexOf('!')));
	return new File(jarurl.toURI());
	}

	public static class MyCharSeq implements CharSequence {
	final String seq = GcFreeLoggingTestUtil.class.toString();

	@Override
	public int length() {
	return seq.length();
	}

	@Override
	public char charAt(final int index) {
	return seq.charAt(index);
	}

	@Override
	public CharSequence subSequence(final int start, final int end) {
	return seq.subSequence(start, end);
	}

	@Override
	public String toString() {
	System.err.println("TEMP OBJECT CREATED!");
	throw new IllegalStateException("TEMP OBJECT CREATED!");
	}
	}
	}