diff --git a/src/main/java/com/intellij/rt/debugger/agent/LogCaptureTransformer.java b/src/main/java/com/intellij/rt/debugger/agent/LogCaptureTransformer.java index 475a32a..302b7ae 100644 --- a/src/main/java/com/intellij/rt/debugger/agent/LogCaptureTransformer.java +++ b/src/main/java/com/intellij/rt/debugger/agent/LogCaptureTransformer.java @@ -4,6 +4,7 @@ import org.jetbrains.capture.org.objectweb.asm.ClassWriter; import org.jetbrains.capture.org.objectweb.asm.MethodVisitor; import org.jetbrains.capture.org.objectweb.asm.Opcodes; +import org.jetbrains.capture.org.objectweb.asm.tree.*; import java.io.FileOutputStream; import java.lang.instrument.ClassFileTransformer; @@ -43,7 +44,7 @@ public byte[] transform(ClassLoader loader, return transformer.accept(new ClassVisitor(Opcodes.API_VERSION, transformer.writer) { @Override public MethodVisitor visitMethod(final int access, String name, String descriptor, String signature, String[] exceptions) { - MethodVisitor superMethodVisitor = super.visitMethod(access, name, descriptor, signature, exceptions); + final MethodVisitor superMethodVisitor = super.visitMethod(access, name, descriptor, signature, exceptions); if (!"write".equals(name)) return superMethodVisitor; // There are also versions like (B)V, but they are uninteresting in terms of logging capture. @@ -59,23 +60,11 @@ public MethodVisitor visitMethod(final int access, String name, String descripto return superMethodVisitor; } - return new MethodVisitor(api, superMethodVisitor) { + return new MethodNode(api, access, name, descriptor, signature, exceptions) { @Override - public void visitCode() { - super.visitCode(); - mv.visitVarInsn(Opcodes.ALOAD, 0); - mv.visitFieldInsn(Opcodes.GETFIELD, - "java/io/FileOutputStream", - "fd", "Ljava/io/FileDescriptor;"); - mv.visitVarInsn(Opcodes.ALOAD, 1); - if (isWithOffset) { - mv.visitVarInsn(Opcodes.ILOAD, 2); - mv.visitVarInsn(Opcodes.ILOAD, 3); - } - mv.visitMethodInsn(Opcodes.INVOKESTATIC, - getInternalClsName(LogCaptureStorage.class), - "capture", "(Ljava/io/FileDescriptor;[B" + (isWithOffset ? "II" : "") + ")V", - false); + public void visitEnd() { + insertCaptureCall(instructions, isWithOffset); + accept(superMethodVisitor); } }; } @@ -88,4 +77,47 @@ public void visitCode() { } return null; } + + private static void insertCaptureCall(InsnList instructions, boolean isWithOffset) { + LineNumberNode firstLineNumber = findFirstLineNumber(instructions); + InsnList captureCall = createCaptureCall(firstLineNumber, isWithOffset); + instructions.insert(captureCall); + } + + private static LineNumberNode findFirstLineNumber(InsnList instructions) { + for (AbstractInsnNode instruction = instructions.getFirst(); instruction != null; instruction = instruction.getNext()) { + if (instruction instanceof LineNumberNode) { + return (LineNumberNode) instruction; + } + } + return null; + } + + /** + * Generates capture call bytecode with a line number mark (if lineNumber is not null). + *

+ * It makes the instrumented code have a valid line number when a stack trace is collected. + */ + private static InsnList createCaptureCall(LineNumberNode lineNumber, boolean isWithOffset) { + InsnList instructions = new InsnList(); + if (lineNumber != null) { + LabelNode labelNode = new LabelNode(); + instructions.add(new LineNumberNode(lineNumber.line, labelNode)); + instructions.add(labelNode); + } + instructions.add(new VarInsnNode(Opcodes.ALOAD, 0)); + instructions.add(new FieldInsnNode(Opcodes.GETFIELD, + "java/io/FileOutputStream", + "fd", "Ljava/io/FileDescriptor;")); + instructions.add(new VarInsnNode(Opcodes.ALOAD, 1)); + if (isWithOffset) { + instructions.add(new VarInsnNode(Opcodes.ILOAD, 2)); + instructions.add(new VarInsnNode(Opcodes.ILOAD, 3)); + } + instructions.add(new MethodInsnNode(Opcodes.INVOKESTATIC, + getInternalClsName(LogCaptureStorage.class), + "capture", "(Ljava/io/FileDescriptor;[B" + (isWithOffset ? "II" : "") + ")V", + false)); + return instructions; + } } diff --git a/src/test/java/com/intellij/rt/debugger/agent/LogCaptureEncodingTest.java b/src/test/java/com/intellij/rt/debugger/agent/LogCaptureEncodingTest.java index 15f86ac..4d27df4 100644 --- a/src/test/java/com/intellij/rt/debugger/agent/LogCaptureEncodingTest.java +++ b/src/test/java/com/intellij/rt/debugger/agent/LogCaptureEncodingTest.java @@ -9,6 +9,7 @@ import java.io.IOException; import java.nio.charset.StandardCharsets; import java.util.ArrayList; +import java.util.List; import java.util.Properties; import java.util.zip.GZIPInputStream; @@ -121,39 +122,49 @@ public void keepsEventIdsAndOrderingAcrossMultipleFlushes() throws Exception { } } - private static DataInputStream openDump(int index) throws IOException { + static DataInputStream openDump(int index) throws IOException { String output = LogCaptureStorage.outputWrittenDumpForTests.get(index); return new DataInputStream(new GZIPInputStream(new ByteArrayInputStream(output.getBytes(StandardCharsets.ISO_8859_1)))); } - private static void readAndCheckStdoutEvent(int expectedId, String expectedMsg, DataInputStream is) throws IOException { + static List readAndCheckStdoutEvent(int expectedId, String expectedMsg, DataInputStream is) throws IOException { assertEquals(expectedId, is.readLong()); assertEquals(LogCaptureStorage.Event.STD_OUTPUT_TYPE, is.readByte()); try (DataInputStream eis = new DataInputStream(new ByteArrayInputStream(readBytesWithSize(is)))) { - readAndCheckMessageAndStack(expectedMsg, eis); + return readAndCheckMessageAndStack(expectedMsg, eis); } } - private static void readAndCheckLoggingBreakpointEvent(int expectedId, - int expectedInstrumentationId, - String expectedMsg, - DataInputStream is) throws IOException { + private static List readAndCheckLoggingBreakpointEvent(int expectedId, + int expectedInstrumentationId, + String expectedMsg, + DataInputStream is) throws IOException { assertEquals(expectedId, is.readLong()); assertEquals(LogCaptureStorage.Event.LOGGING_BREAKPOINT_TYPE, is.readByte()); try (DataInputStream eis = new DataInputStream(new ByteArrayInputStream(readBytesWithSize(is)))) { assertEquals(expectedInstrumentationId, eis.readInt()); - readAndCheckMessageAndStack(expectedMsg, eis); + return readAndCheckMessageAndStack(expectedMsg, eis); } } - private static void readAndCheckMessageAndStack(String expectedMsg, DataInputStream is) throws IOException { + static List readAndCheckMessageAndStack(String expectedMsg, DataInputStream is) throws IOException { byte[] msgBytes = readBytesWithSize(is); String msg = new String(msgBytes, StandardCharsets.UTF_8); assertEquals(expectedMsg, msg); assertTrue("expected encoded stack trace after message", is.available() > 0); + ArrayList stack = new ArrayList<>(); + while (is.available() > 0) { + boolean regularFrame = is.readBoolean(); + if (regularFrame) { + stack.add(new StackTraceElement(is.readUTF(), is.readUTF(), null, is.readInt())); + } else { + stack.add(null); + } + } + return stack; } - private static byte[] readBytesWithSize(DataInputStream is) throws IOException { + static byte[] readBytesWithSize(DataInputStream is) throws IOException { // Performance is not critical, just do it in a loop missing Java 11 readNBytes(). int size = is.readInt(); byte[] bytes = new byte[size]; @@ -163,7 +174,7 @@ private static byte[] readBytesWithSize(DataInputStream is) throws IOException { return bytes; } - private static void resetLogCaptureStorage() { + static void resetLogCaptureStorage() { LogCaptureStorage.EVENT_COUNTER.set(0); LogCaptureStorage.LAST_FLUSHED_EVENT_ID.set(-1); LogCaptureStorage.LAST_LOGGING_BREAKPOINT_EVENT_ID.set(-1); diff --git a/src/test/java/com/intellij/rt/debugger/agent/LogCaptureTransformerTest.java b/src/test/java/com/intellij/rt/debugger/agent/LogCaptureTransformerTest.java new file mode 100644 index 0000000..f5d4522 --- /dev/null +++ b/src/test/java/com/intellij/rt/debugger/agent/LogCaptureTransformerTest.java @@ -0,0 +1,279 @@ +package com.intellij.rt.debugger.agent; + +import org.jetbrains.capture.org.objectweb.asm.*; +import org.jetbrains.capture.org.objectweb.asm.commons.ClassRemapper; +import org.jetbrains.capture.org.objectweb.asm.commons.SimpleRemapper; +import org.jetbrains.capture.org.objectweb.asm.tree.*; +import org.junit.Assert; +import org.junit.Before; +import org.junit.Test; + +import java.io.*; +import java.lang.reflect.Constructor; +import java.lang.reflect.Method; +import java.nio.charset.StandardCharsets; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.Properties; + +public class LogCaptureTransformerTest { + private static final String WRITE_DESCRIPTOR = "([BII)V"; + private static final String TEST_FILE_OUTPUT_STREAM = "test/InstrumentedFileOutputStream"; + + @Before + public void setUp() { + Assert.assertEquals( + "Please disable the agent if you try to debug this test. " + + "Otherwise, you debug the bundled agent and not the code in the project.", + this.getClass().getClassLoader(), LogCaptureStorage.class.getClassLoader()); + LogCaptureEncodingTest.resetLogCaptureStorage(); + } + + @Test + public void insertsCaptureAfterFirstLineNumberInWriteMethod() throws IOException { + byte[] classBytes = createFileOutputStreamClass(true); + MethodNode originalWrite = findWriteMethod(classBytes); + MethodNode write = transformWriteMethod(classBytes); + + int lineNumberIndex = indexOfFirstLineNumber(write); + int captureIndex = indexOfCaptureCall(write); + int originalMethodCallIndex = indexOfMethodCall(write, findFirstMethodCall(originalWrite)); + + Assert.assertTrue("test class should contain a line number", lineNumberIndex >= 0); + Assert.assertTrue("capture call should be inserted after the first line number", captureIndex > lineNumberIndex); + Assert.assertTrue("capture call should still run before the original method body", captureIndex < originalMethodCallIndex); + } + + @Test + public void insertsCaptureAtMethodStartWhenWriteMethodHasNoLineNumbers() throws IOException { + byte[] classBytes = createFileOutputStreamClass(false); + MethodNode originalWrite = findWriteMethod(classBytes); + MethodNode write = transformWriteMethod(classBytes); + + int lineNumberIndex = indexOfFirstLineNumber(write); + int captureIndex = indexOfCaptureCall(write); + int originalMethodCallIndex = indexOfMethodCall(write, findFirstMethodCall(originalWrite)); + + Assert.assertEquals("test class should not contain line numbers", -1, lineNumberIndex); + Assert.assertTrue("capture call should be inserted", captureIndex >= 0); + Assert.assertTrue("capture call should run before the original method body", captureIndex < originalMethodCallIndex); + } + + @Test + public void instrumentedWriteCapturesStackWithTopFrameLineNumber() throws Exception { + Properties properties = new Properties(); + properties.put(LogCaptureStorage.BATCHING_ENABLED_PROPERTY, "false"); + LogCaptureStorage.outputWrittenDumpForTests = new ArrayList<>(); + LogCaptureStorage.init(properties, true); + + byte[] loadableClass = prepareFileOutputStreamForTestLoading(readFileOutputStreamClass()); + Class loadedClass = new TestClassLoader().define(loadableClass); + + Constructor constructor = loadedClass.getConstructor(FileDescriptor.class); + Object instance = constructor.newInstance(FileDescriptor.out); + + Method write = loadedClass.getMethod("write", byte[].class, int.class, int.class); + String message = "test message"; + byte[] messageBytes = message.getBytes(StandardCharsets.UTF_8); + write.invoke(instance, messageBytes, 0, messageBytes.length); + + StackTraceElement topFrame = readCapturedTopFrame(message); + Assert.assertEquals(TEST_FILE_OUTPUT_STREAM.replace('/', '.'), topFrame.getClassName()); + Assert.assertEquals("write", topFrame.getMethodName()); + Assert.assertTrue("top stack frame should have a real line number: " + topFrame, topFrame.getLineNumber() > 0); + } + + private static MethodNode transformWriteMethod(byte[] classBytes) { + byte[] transformed = transformFileOutputStreamClass(classBytes); + + Assert.assertNotNull(transformed); + return findWriteMethod(transformed); + } + + private static byte[] transformFileOutputStreamClass(byte[] classBytes) { + return new LogCaptureTransformer().transform( + LogCaptureTransformerTest.class.getClassLoader(), + LogCaptureTransformer.CLASS_NAME, + null, + null, + classBytes + ); + } + + private static byte[] createFileOutputStreamClass(boolean withLineNumbers) throws IOException { + byte[] classBytes = readFileOutputStreamClass(); + if (withLineNumbers) { + return classBytes; + } + return removeLineNumbers(classBytes); + } + + private static byte[] readFileOutputStreamClass() throws IOException { + InputStream stream = FileOutputStream.class.getResourceAsStream("FileOutputStream.class"); + Assert.assertNotNull("FileOutputStream bytecode should be available", stream); + try { + ByteArrayOutputStream result = new ByteArrayOutputStream(); + byte[] buffer = new byte[8192]; + int read; + while ((read = stream.read(buffer)) >= 0) { + result.write(buffer, 0, read); + } + return result.toByteArray(); + } finally { + stream.close(); + } + } + + private static byte[] removeLineNumbers(byte[] classBytes) { + ClassReader reader = new ClassReader(classBytes); + ClassWriter writer = new ClassWriter(reader, 0); + reader.accept(new ClassVisitor(Opcodes.API_VERSION, writer) { + @Override + public MethodVisitor visitMethod(int access, String name, String descriptor, String signature, String[] exceptions) { + MethodVisitor methodVisitor = super.visitMethod(access, name, descriptor, signature, exceptions); + return new MethodVisitor(api, methodVisitor) { + @Override + public void visitLineNumber(int line, Label start) { + } + }; + } + }, 0); + return writer.toByteArray(); + } + + private static byte[] prepareFileOutputStreamForTestLoading(byte[] classBytes) { + byte[] transformed = transformFileOutputStreamClass(classBytes); + ClassReader reader = new ClassReader(transformed); + ClassWriter writer = new ClassWriter(reader, ClassWriter.COMPUTE_FRAMES | ClassWriter.COMPUTE_MAXS); + // A regular test ClassLoader cannot define classes in java.* packages. + SimpleRemapper remapper = new SimpleRemapper(Collections.singletonMap(LogCaptureTransformer.CLASS_NAME, TEST_FILE_OUTPUT_STREAM)); + reader.accept(new ClassRemapper(new FileOutputStreamTestClassAdapter(writer), remapper), 0); + return writer.toByteArray(); + } + + private static class FileOutputStreamTestClassAdapter extends ClassVisitor { + + private FileOutputStreamTestClassAdapter(ClassVisitor classVisitor) { + super(Opcodes.API_VERSION, classVisitor); + } + + @Override + public MethodVisitor visitMethod(int access, String name, String descriptor, String signature, String[] exceptions) { + // Keep the injected capture call, but avoid executing FileOutputStream's JDK-internal write tail. + if ("write".equals(name) && WRITE_DESCRIPTOR.equals(descriptor)) { + return new MethodVisitor(api, super.visitMethod(access, name, descriptor, signature, exceptions)) { + @Override + public void visitMethodInsn(int opcode, String owner, String name, String descriptor, boolean isInterface) { + super.visitMethodInsn(opcode, owner, name, descriptor, isInterface); + if (opcode == Opcodes.INVOKESTATIC && getInternalLogCaptureStorageName().equals(owner) && "capture".equals(name)) { + super.visitInsn(Opcodes.RETURN); + } + } + }; + } + // FileOutputStream's class initializer registers native methods for the original JDK class. + if ("".equals(name)) { + return null; + } + // Replace the real constructor with a minimal one that only sets fd. + if ("".equals(name) && "(Ljava/io/FileDescriptor;)V".equals(descriptor)) { + MethodVisitor constructor = super.visitMethod(access, name, descriptor, signature, exceptions); + constructor.visitCode(); + constructor.visitVarInsn(Opcodes.ALOAD, 0); + constructor.visitMethodInsn(Opcodes.INVOKESPECIAL, "java/io/OutputStream", "", "()V", false); + constructor.visitVarInsn(Opcodes.ALOAD, 0); + constructor.visitVarInsn(Opcodes.ALOAD, 1); + constructor.visitFieldInsn(Opcodes.PUTFIELD, TEST_FILE_OUTPUT_STREAM, "fd", "Ljava/io/FileDescriptor;"); + constructor.visitInsn(Opcodes.RETURN); + constructor.visitMaxs(2, 2); + constructor.visitEnd(); + return null; + } + return super.visitMethod(access, name, descriptor, signature, exceptions); + } + } + + private static StackTraceElement readCapturedTopFrame(String expectedMsg) throws IOException { + Assert.assertEquals(1, LogCaptureStorage.outputWrittenDumpForTests.size()); + try (DataInputStream is = LogCaptureEncodingTest.openDump(0)) { + Assert.assertEquals(1, is.readInt()); // count + List stack = LogCaptureEncodingTest.readAndCheckStdoutEvent(-1, expectedMsg, is); + Assert.assertFalse("expected captured stack", stack.isEmpty()); + return stack.get(0); + } + } + + private static MethodNode findWriteMethod(byte[] classBytes) { + ClassNode classNode = new ClassNode(); + new ClassReader(classBytes).accept(classNode, 0); + for (MethodNode method : classNode.methods) { + if ("write".equals(method.name) && WRITE_DESCRIPTOR.equals(method.desc)) { + return method; + } + } + Assert.fail("write method was not found"); + return null; + } + + private static int indexOfFirstLineNumber(MethodNode method) { + for (int i = 0; i < method.instructions.size(); i++) { + if (method.instructions.get(i) instanceof LineNumberNode) { + return i; + } + } + return -1; + } + + private static int indexOfCaptureCall(MethodNode method) { + for (int i = 0; i < method.instructions.size(); i++) { + AbstractInsnNode instruction = method.instructions.get(i); + if (instruction instanceof MethodInsnNode) { + MethodInsnNode methodInsnNode = (MethodInsnNode) instruction; + if (methodInsnNode.getOpcode() == Opcodes.INVOKESTATIC && + getInternalLogCaptureStorageName().equals(methodInsnNode.owner) && + "capture".equals(methodInsnNode.name)) { + return i; + } + } + } + return -1; + } + + private static MethodInsnNode findFirstMethodCall(MethodNode method) { + for (int i = 0; i < method.instructions.size(); i++) { + AbstractInsnNode instruction = method.instructions.get(i); + if (instruction instanceof MethodInsnNode) { + return (MethodInsnNode) instruction; + } + } + Assert.fail("method call was not found"); + return null; + } + + private static int indexOfMethodCall(MethodNode method, MethodInsnNode expected) { + for (int i = 0; i < method.instructions.size(); i++) { + AbstractInsnNode instruction = method.instructions.get(i); + if (instruction instanceof MethodInsnNode) { + MethodInsnNode methodInsnNode = (MethodInsnNode) instruction; + if (methodInsnNode.getOpcode() == expected.getOpcode() && + methodInsnNode.owner.equals(expected.owner) && + methodInsnNode.name.equals(expected.name) && + methodInsnNode.desc.equals(expected.desc)) { + return i; + } + } + } + return -1; + } + + private static String getInternalLogCaptureStorageName() { + return LogCaptureStorage.class.getName().replace('.', '/'); + } + + private static class TestClassLoader extends ClassLoader { + private Class define(byte[] classBytes) { + return defineClass(TEST_FILE_OUTPUT_STREAM.replace('/', '.'), classBytes, 0, classBytes.length); + } + } +}