From b375d0fc0478d399f035b91d8b2fb8b3a6a32bb7 Mon Sep 17 00:00:00 2001 From: Sergey Grigorchuk Date: Wed, 21 Jan 2026 16:01:35 +0000 Subject: [PATCH 1/3] Log Context MVP --- .gitignore | 5 +- CHANGELOG.md | 1 + README.md | 20 +- RELEASE_NOTES_0.2.3.md | 1 + .../org/kolobok/annotation/LogContext.java | 11 + kolobok-transformer/pom.xml | 6 + .../transformer/KolobokTransformer.java | 369 +++++++++++++++++- .../LogContextIntegrationTest.java | 115 ++++++ .../transformer/LogContextLineNumberTest.java | 126 ++++++ .../com/example/kolobok/PersonRepository.java | 4 +- .../com/example/kolobok/PersonController.java | 7 + .../com/example/kolobok/PersonRepository.java | 4 +- 12 files changed, 657 insertions(+), 12 deletions(-) create mode 100644 kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java create mode 100644 kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java create mode 100644 kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java diff --git a/.gitignore b/.gitignore index c31e935..54ba870 100644 --- a/.gitignore +++ b/.gitignore @@ -28,6 +28,5 @@ PUBLISHING_PRIVATE.md token.xml # Local run scripts -samples/spring-data-jpa-maven/run-java*.sh -samples/spring-data-jpa-gradle/run-java*.sh -compile2.sh +**/run-java*.sh +**/compile*.sh diff --git a/CHANGELOG.md b/CHANGELOG.md index 8de622c..0589946 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ All notable changes to this project will be documented in this file. ## 0.2.3 - Verified support for Java 11+ (tested on 11, 17, 21, 25) and updated build targets accordingly. +- Added `@LogContext` annotation with bytecode instrumentation for method entry/exit/exception logging using existing SLF4J logger fields. - Updated sample and example dependencies to 0.2.3. ## 0.2.0 diff --git a/README.md b/README.md index 069423d..460fc99 100644 --- a/README.md +++ b/README.md @@ -13,7 +13,7 @@ But if you want to find only by `cityId` and `lastName` (without specifying `fir ```java List findByLastNameAndCityId(String lastName, Long cityId); ``` -`@FindWithOptionalParams` annotation allows you to use original `findByFirstNameAndLastNameAndCityId` method with `null` values for params which should not be used in search criteria. +`@FindWithOptionalParams` annotation allows you to use original `findByFirstNameAndLastNameAndCityId` method with `null` values for params which should not be used in search criteria. If the return type is `List`, ensure your repository exposes a `findAll()` that returns `List` (for example by extending `JpaRepository`). ```java @Repository public interface PersonRepo extends PagingAndSortingRepository { @@ -71,6 +71,24 @@ Also it generates default implementation of `findByFirstNameAndLastNameAndCityId } ``` +## @LogContext +`@LogContext` logs method entry (arguments), return values, exceptions, and execution time using an existing logger field on the class. The transformer looks for a static logger field named `log`, `logger`, `LOG`, or `LOGGER` with type `org.slf4j.Logger`. Entry/exit logs are emitted at `debug`, exceptions at `error`. + +```java +import org.kolobok.annotation.LogContext; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class SampleService { + private static final Logger log = LoggerFactory.getLogger(SampleService.class); + + @LogContext + public String work(String name, int count) { + return name + count; + } +} +``` + ## How to use Kolobok? Kolobok uses a bytecode transformer after compilation, so no special compiler flags are needed. It works on Java 11 and newer (verified on 11, 17, 21, 25). diff --git a/RELEASE_NOTES_0.2.3.md b/RELEASE_NOTES_0.2.3.md index 4984a9c..8557b3d 100644 --- a/RELEASE_NOTES_0.2.3.md +++ b/RELEASE_NOTES_0.2.3.md @@ -2,6 +2,7 @@ ## Highlights - Verified Java 11+ compatibility (tested on 11, 17, 21, 25) and adjusted build targets. +- Added `@LogContext` instrumentation that logs method entry/exit/exception timing using existing SLF4J logger fields. - Updated samples and example dependencies to 0.2.3. ## Compatibility diff --git a/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java b/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java new file mode 100644 index 0000000..bd4f895 --- /dev/null +++ b/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java @@ -0,0 +1,11 @@ +package org.kolobok.annotation; + +import java.lang.annotation.ElementType; +import java.lang.annotation.Retention; +import java.lang.annotation.RetentionPolicy; +import java.lang.annotation.Target; + +@Retention(RetentionPolicy.CLASS) +@Target({ElementType.TYPE, ElementType.METHOD}) +public @interface LogContext { +} diff --git a/kolobok-transformer/pom.xml b/kolobok-transformer/pom.xml index 0ad827e..97beff4 100644 --- a/kolobok-transformer/pom.xml +++ b/kolobok-transformer/pom.xml @@ -39,6 +39,12 @@ assertj-core test + + org.slf4j + slf4j-api + 2.0.16 + test + junit junit diff --git a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java index 4b32b33..6e88f0b 100644 --- a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java +++ b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java @@ -6,9 +6,22 @@ import org.objectweb.asm.Type; import org.objectweb.asm.commons.GeneratorAdapter; import org.objectweb.asm.commons.Method; +import org.objectweb.asm.tree.AbstractInsnNode; import org.objectweb.asm.tree.AnnotationNode; import org.objectweb.asm.tree.ClassNode; +import org.objectweb.asm.tree.FieldNode; +import org.objectweb.asm.tree.FieldInsnNode; +import org.objectweb.asm.tree.IntInsnNode; +import org.objectweb.asm.tree.InsnList; +import org.objectweb.asm.tree.InsnNode; +import org.objectweb.asm.tree.JumpInsnNode; +import org.objectweb.asm.tree.LabelNode; +import org.objectweb.asm.tree.LdcInsnNode; +import org.objectweb.asm.tree.MethodInsnNode; import org.objectweb.asm.tree.MethodNode; +import org.objectweb.asm.tree.TryCatchBlockNode; +import org.objectweb.asm.tree.TypeInsnNode; +import org.objectweb.asm.tree.VarInsnNode; import java.io.IOException; import java.nio.file.Files; @@ -22,6 +35,9 @@ public class KolobokTransformer { public static final String OPTIONAL_PARAMS_DESC = "Lorg/kolobok/annotation/FindWithOptionalParams;"; + public static final String LOG_CONTEXT_DESC = "Lorg/kolobok/annotation/LogContext;"; + private static final String SLF4J_LOGGER_DESC = "Lorg/slf4j/Logger;"; + private static final String[] LOGGER_FIELD_NAMES = {"log", "logger", "LOG", "LOGGER"}; private final RepoMethodUtil repoMethodUtil = new RepoMethodUtil(); @@ -45,11 +61,12 @@ public void transformClassFile(Path classFile) throws IOException { ClassNode classNode = new ClassNode(); reader.accept(classNode, ClassReader.EXPAND_FRAMES); - if ((classNode.access & Opcodes.ACC_INTERFACE) == 0) { - return; + boolean modified; + if ((classNode.access & Opcodes.ACC_INTERFACE) != 0) { + modified = transformInterface(classNode); + } else { + modified = transformLogContext(classNode); } - - boolean modified = transformInterface(classNode); if (!modified) { return; } @@ -97,6 +114,338 @@ private boolean transformInterface(ClassNode classNode) { return true; } + private boolean transformLogContext(ClassNode classNode) { + boolean classAnnotated = hasAnnotation(classNode.visibleAnnotations, LOG_CONTEXT_DESC) + || hasAnnotation(classNode.invisibleAnnotations, LOG_CONTEXT_DESC); + + List methodsToInstrument = new ArrayList<>(); + for (MethodNode method : classNode.methods) { + if (shouldInstrumentMethod(method, classAnnotated)) { + methodsToInstrument.add(method); + } + } + + if (methodsToInstrument.isEmpty()) { + return false; + } + + FieldNode loggerField = findLoggerField(classNode); + if (loggerField == null) { + throw new IllegalStateException("Class '" + classNode.name + + "' uses @LogContext but no static logger field named log/logger/LOG/LOGGER with type org.slf4j.Logger was found"); + } + + for (MethodNode method : methodsToInstrument) { + instrumentLogContextMethod(classNode, method, loggerField); + } + + return true; + } + + private boolean shouldInstrumentMethod(MethodNode method, boolean classAnnotated) { + if ((method.access & (Opcodes.ACC_ABSTRACT | Opcodes.ACC_NATIVE)) != 0) { + return false; + } + if (method.name.equals("") || method.name.equals("")) { + return false; + } + if (method.instructions == null || method.instructions.size() == 0) { + return false; + } + return classAnnotated || hasAnnotation(method, LOG_CONTEXT_DESC); + } + + private FieldNode findLoggerField(ClassNode classNode) { + for (FieldNode field : classNode.fields) { + if ((field.access & Opcodes.ACC_STATIC) == 0) { + continue; + } + if (!SLF4J_LOGGER_DESC.equals(field.desc)) { + continue; + } + for (String name : LOGGER_FIELD_NAMES) { + if (name.equals(field.name)) { + return field; + } + } + } + return null; + } + + private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, FieldNode loggerField) { + boolean isStatic = (method.access & Opcodes.ACC_STATIC) != 0; + Type[] argTypes = Type.getArgumentTypes(method.desc); + Type returnType = Type.getReturnType(method.desc); + int[] argIndexes = computeArgIndexes(isStatic, argTypes); + + int startTimeVar = method.maxLocals; + method.maxLocals += 2; + + int returnVar = -1; + if (returnType.getSort() != Type.VOID) { + returnVar = method.maxLocals; + method.maxLocals += returnType.getSize(); + } + + int durationVar = method.maxLocals; + method.maxLocals += 2; + + int exceptionVar = method.maxLocals; + method.maxLocals += 1; + + LabelNode startLabel = new LabelNode(); + LabelNode endLabel = new LabelNode(); + LabelNode handlerLabel = new LabelNode(); + + InsnList entry = new InsnList(); + entry.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); + entry.add(new VarInsnNode(Opcodes.LSTORE, startTimeVar)); + append(entry, buildEntryLog(classNode, method, loggerField, argTypes, argIndexes)); + entry.add(startLabel); + method.instructions.insert(entry); + + List returns = new ArrayList<>(); + for (AbstractInsnNode insn = method.instructions.getFirst(); insn != null; insn = insn.getNext()) { + int opcode = insn.getOpcode(); + if (opcode >= Opcodes.IRETURN && opcode <= Opcodes.RETURN) { + returns.add(insn); + } + } + + for (AbstractInsnNode ret : returns) { + InsnList exit = new InsnList(); + int opcode = ret.getOpcode(); + if (returnType.getSort() == Type.VOID) { + append(exit, buildExitLog(classNode, method, loggerField, startTimeVar, durationVar, null, null)); + exit.add(new InsnNode(Opcodes.RETURN)); + } else { + exit.add(new VarInsnNode(returnType.getOpcode(Opcodes.ISTORE), returnVar)); + append(exit, buildExitLog(classNode, method, loggerField, startTimeVar, durationVar, returnType, returnVar)); + exit.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); + exit.add(new InsnNode(opcode)); + } + method.instructions.insertBefore(ret, exit); + method.instructions.remove(ret); + } + + InsnList handler = new InsnList(); + handler.add(endLabel); + handler.add(handlerLabel); + handler.add(new VarInsnNode(Opcodes.ASTORE, exceptionVar)); + append(handler, buildErrorLog(classNode, method, loggerField, startTimeVar, durationVar, exceptionVar)); + handler.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); + handler.add(new InsnNode(Opcodes.ATHROW)); + method.instructions.add(handler); + + method.tryCatchBlocks.add(new TryCatchBlockNode(startLabel, endLabel, handlerLabel, "java/lang/Throwable")); + } + + private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode loggerField, + Type[] argTypes, int[] argIndexes) { + InsnList insns = new InsnList(); + LabelNode skipLabel = new LabelNode(); + + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "isDebugEnabled", "()Z", true)); + insns.add(new JumpInsnNode(Opcodes.IFEQ, skipLabel)); + + append(insns, buildArgsArray(argTypes, argIndexes)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/util/Arrays", "deepToString", + "([Ljava/lang/Object;)Ljava/lang/String;", false)); + + String prefix = "Enter " + toHumanName(classNode.name) + "#" + method.name + " args="; + insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); + insns.add(new InsnNode(Opcodes.DUP)); + insns.add(new LdcInsnNode(prefix)); + insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", + "(Ljava/lang/String;)V", false)); + insns.add(new InsnNode(Opcodes.SWAP)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", + "()Ljava/lang/String;", false)); + + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new InsnNode(Opcodes.SWAP)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "debug", + "(Ljava/lang/String;)V", true)); + + insns.add(skipLabel); + return insns; + } + + private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode loggerField, + int startTimeVar, int durationVar, Type returnType, Integer returnVar) { + InsnList insns = new InsnList(); + LabelNode skipLabel = new LabelNode(); + + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "isDebugEnabled", "()Z", true)); + insns.add(new JumpInsnNode(Opcodes.IFEQ, skipLabel)); + + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, startTimeVar)); + insns.add(new InsnNode(Opcodes.LSUB)); + insns.add(new VarInsnNode(Opcodes.LSTORE, durationVar)); + + String prefix = "Exit " + toHumanName(classNode.name) + "#" + method.name + " result="; + insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); + insns.add(new InsnNode(Opcodes.DUP)); + insns.add(new LdcInsnNode(prefix)); + insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", + "(Ljava/lang/String;)V", false)); + + if (returnType == null) { + insns.add(new LdcInsnNode("void")); + } else { + insns.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); + boxValue(insns, returnType); + } + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", + "(Ljava/lang/Object;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + + insns.add(new LdcInsnNode(" took=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("ns")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", + "()Ljava/lang/String;", false)); + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new InsnNode(Opcodes.SWAP)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "debug", + "(Ljava/lang/String;)V", true)); + + insns.add(skipLabel); + return insns; + } + + private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode loggerField, + int startTimeVar, int durationVar, int exceptionVar) { + InsnList insns = new InsnList(); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, startTimeVar)); + insns.add(new InsnNode(Opcodes.LSUB)); + insns.add(new VarInsnNode(Opcodes.LSTORE, durationVar)); + + String prefix = "Error " + toHumanName(classNode.name) + "#" + method.name + " took="; + insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); + insns.add(new InsnNode(Opcodes.DUP)); + insns.add(new LdcInsnNode(prefix)); + insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", + "(Ljava/lang/String;)V", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("ns")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", + "()Ljava/lang/String;", false)); + + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new InsnNode(Opcodes.SWAP)); + insns.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "error", + "(Ljava/lang/String;Ljava/lang/Throwable;)V", true)); + return insns; + } + + private InsnList buildArgsArray(Type[] argTypes, int[] argIndexes) { + InsnList insns = new InsnList(); + pushInt(insns, argTypes.length); + insns.add(new TypeInsnNode(Opcodes.ANEWARRAY, "java/lang/Object")); + for (int i = 0; i < argTypes.length; i++) { + Type type = argTypes[i]; + insns.add(new InsnNode(Opcodes.DUP)); + pushInt(insns, i); + insns.add(new VarInsnNode(type.getOpcode(Opcodes.ILOAD), argIndexes[i])); + boxValue(insns, type); + insns.add(new InsnNode(Opcodes.AASTORE)); + } + return insns; + } + + private void boxValue(InsnList insns, Type type) { + switch (type.getSort()) { + case Type.BOOLEAN: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Boolean", "valueOf", + "(Z)Ljava/lang/Boolean;", false)); + break; + case Type.BYTE: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Byte", "valueOf", + "(B)Ljava/lang/Byte;", false)); + break; + case Type.CHAR: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Character", "valueOf", + "(C)Ljava/lang/Character;", false)); + break; + case Type.SHORT: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Short", "valueOf", + "(S)Ljava/lang/Short;", false)); + break; + case Type.INT: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Integer", "valueOf", + "(I)Ljava/lang/Integer;", false)); + break; + case Type.FLOAT: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Float", "valueOf", + "(F)Ljava/lang/Float;", false)); + break; + case Type.LONG: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Long", "valueOf", + "(J)Ljava/lang/Long;", false)); + break; + case Type.DOUBLE: + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Double", "valueOf", + "(D)Ljava/lang/Double;", false)); + break; + default: + break; + } + } + + private void pushInt(InsnList insns, int value) { + if (value == -1) { + insns.add(new InsnNode(Opcodes.ICONST_M1)); + } else if (value >= 0 && value <= 5) { + insns.add(new InsnNode(Opcodes.ICONST_0 + value)); + } else if (value <= Byte.MAX_VALUE) { + insns.add(new IntInsnNode(Opcodes.BIPUSH, value)); + } else if (value <= Short.MAX_VALUE) { + insns.add(new IntInsnNode(Opcodes.SIPUSH, value)); + } else { + insns.add(new LdcInsnNode(value)); + } + } + + private int[] computeArgIndexes(boolean isStatic, Type[] argTypes) { + int[] indexes = new int[argTypes.length]; + int idx = isStatic ? 0 : 1; + for (int i = 0; i < argTypes.length; i++) { + indexes[i] = idx; + idx += argTypes[i].getSize(); + } + return indexes; + } + + private String toHumanName(String internalName) { + return internalName.replace('/', '.'); + } + + private void append(InsnList target, InsnList source) { + for (AbstractInsnNode node : source.toArray()) { + target.add(node); + } + } + private void validateReturnType(MethodNode method, RepoMethod repoMethod) { Type returnType = Type.getReturnType(method.desc); if (repoMethod.getType() == RepoMethod.Type.FIND) { @@ -310,6 +659,18 @@ private boolean hasAnnotation(MethodNode method, String desc) { return false; } + private boolean hasAnnotation(List annotations, String desc) { + if (annotations == null) { + return false; + } + for (AnnotationNode annotation : annotations) { + if (desc.equals(annotation.desc)) { + return true; + } + } + return false; + } + private String signature(MethodNode method) { return method.name + method.desc; } diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java new file mode 100644 index 0000000..9377c85 --- /dev/null +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java @@ -0,0 +1,115 @@ +package org.kolobok.transformer; + +import org.junit.Test; +import org.objectweb.asm.ClassReader; +import org.objectweb.asm.tree.ClassNode; +import org.objectweb.asm.tree.MethodInsnNode; +import org.objectweb.asm.tree.MethodNode; + +import javax.tools.Diagnostic; +import javax.tools.DiagnosticCollector; +import javax.tools.JavaCompiler; +import javax.tools.JavaFileObject; +import javax.tools.StandardJavaFileManager; +import javax.tools.ToolProvider; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.List; +import java.util.Optional; + +import static org.assertj.core.api.Assertions.assertThat; + +public class LogContextIntegrationTest { + + @Test + public void instrumentsAnnotatedMethod() throws Exception { + Path tempDir = Files.createTempDirectory("kolobok-log-it"); + Path srcDir = tempDir.resolve("src"); + Path classesDir = tempDir.resolve("classes"); + Files.createDirectories(srcDir.resolve("sample")); + Files.createDirectories(classesDir); + + writeSources(srcDir); + compileSources(srcDir, classesDir); + + Path classFile = classesDir.resolve("sample/SampleService.class"); + KolobokTransformer transformer = new KolobokTransformer(); + transformer.transformClassFile(classFile); + + ClassNode classNode = readClassNode(classFile); + MethodNode method = findMethod(classNode, "work", "(Ljava/lang/String;I)Ljava/lang/String;"); + assertThat(method).isNotNull(); + + boolean hasDebugLog = Arrays.stream(method.instructions.toArray()) + .filter(node -> node instanceof MethodInsnNode) + .map(node -> (MethodInsnNode) node) + .anyMatch(node -> "org/slf4j/Logger".equals(node.owner) && "debug".equals(node.name)); + assertThat(hasDebugLog).isTrue(); + } + + private void writeSources(Path srcDir) throws IOException { + String service = String.join("\n", + "package sample;", + "", + "import org.kolobok.annotation.LogContext;", + "import org.slf4j.Logger;", + "import org.slf4j.LoggerFactory;", + "", + "public class SampleService {", + " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", + "", + " @LogContext", + " public String work(String name, int count) {", + " return name + count;", + " }", + "}", + "" + ); + Files.writeString(srcDir.resolve("sample/SampleService.java"), service); + } + + private void compileSources(Path srcDir, Path classesDir) throws IOException { + JavaCompiler compiler = ToolProvider.getSystemJavaCompiler(); + assertThat(compiler).as("System Java compiler is available").isNotNull(); + + DiagnosticCollector diagnostics = new DiagnosticCollector<>(); + StandardJavaFileManager fileManager = compiler.getStandardFileManager(diagnostics, null, null); + Iterable units = fileManager.getJavaFileObjectsFromFiles( + Arrays.asList(srcDir.resolve("sample/SampleService.java").toFile()) + ); + + List options = Arrays.asList( + "-d", classesDir.toString(), + "-classpath", System.getProperty("java.class.path") + ); + + Boolean result = compiler.getTask(null, fileManager, diagnostics, options, null, units).call(); + fileManager.close(); + + if (result == null || !result) { + StringBuilder sb = new StringBuilder("Compilation failed:\n"); + for (Diagnostic diagnostic : diagnostics.getDiagnostics()) { + sb.append(diagnostic.getKind()).append(": ") + .append(diagnostic.getMessage(null)).append("\n"); + } + throw new IllegalStateException(sb.toString()); + } + } + + private ClassNode readClassNode(Path classFile) throws IOException { + byte[] bytes = Files.readAllBytes(classFile); + ClassReader reader = new ClassReader(bytes); + ClassNode node = new ClassNode(); + reader.accept(node, ClassReader.SKIP_DEBUG | ClassReader.SKIP_FRAMES); + return node; + } + + private MethodNode findMethod(ClassNode classNode, String name, String desc) { + Optional method = classNode.methods.stream() + .filter(m -> m.name.equals(name) && m.desc.equals(desc)) + .findFirst(); + return method.orElse(null); + } +} diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java new file mode 100644 index 0000000..3b59af5 --- /dev/null +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java @@ -0,0 +1,126 @@ +package org.kolobok.transformer; + +import org.junit.Test; + +import javax.tools.Diagnostic; +import javax.tools.DiagnosticCollector; +import javax.tools.JavaCompiler; +import javax.tools.JavaFileObject; +import javax.tools.StandardJavaFileManager; +import javax.tools.ToolProvider; +import java.io.IOException; +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +import java.net.URL; +import java.net.URLClassLoader; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.List; + +import static org.assertj.core.api.Assertions.assertThat; + +public class LogContextLineNumberTest { + + @Test + public void preservesLineNumberForThrownException() throws Exception { + Path tempDir = Files.createTempDirectory("kolobok-log-lines"); + Path srcDir = tempDir.resolve("src"); + Path classesDir = tempDir.resolve("classes"); + Files.createDirectories(srcDir.resolve("sample")); + Files.createDirectories(classesDir); + + int expectedLine = writeSources(srcDir); + compileSources(srcDir, classesDir); + + Path classFile = classesDir.resolve("sample/SampleService.class"); + KolobokTransformer transformer = new KolobokTransformer(); + transformer.transformClassFile(classFile); + + try (URLClassLoader loader = new URLClassLoader(new URL[]{classesDir.toUri().toURL()}, + Thread.currentThread().getContextClassLoader())) { + Class clazz = loader.loadClass("sample.SampleService"); + Object instance = clazz.getDeclaredConstructor().newInstance(); + Method explode = clazz.getMethod("explode"); + try { + explode.invoke(instance); + } catch (InvocationTargetException ex) { + Throwable cause = ex.getCause(); + assertThat(cause).isInstanceOf(IllegalStateException.class); + int actualLine = findLine(cause.getStackTrace(), "sample.SampleService", "explode"); + assertThat(actualLine).isEqualTo(expectedLine); + return; + } + } + + throw new AssertionError("Expected exception was not thrown"); + } + + private int writeSources(Path srcDir) throws IOException { + String[] lines = new String[]{ + "package sample;", + "", + "import org.kolobok.annotation.LogContext;", + "import org.slf4j.Logger;", + "import org.slf4j.LoggerFactory;", + "", + "public class SampleService {", + " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", + "", + " @LogContext", + " public void explode() {", + " throw new IllegalStateException(\"boom\");", + " }", + "}", + "" + }; + Files.writeString(srcDir.resolve("sample/SampleService.java"), String.join("\n", lines)); + return findLine(lines, " throw new IllegalStateException(\"boom\");"); + } + + private int findLine(String[] lines, String needle) { + for (int i = 0; i < lines.length; i++) { + if (needle.equals(lines[i])) { + return i + 1; + } + } + throw new IllegalStateException("Line not found: " + needle); + } + + private void compileSources(Path srcDir, Path classesDir) throws IOException { + JavaCompiler compiler = ToolProvider.getSystemJavaCompiler(); + assertThat(compiler).as("System Java compiler is available").isNotNull(); + + DiagnosticCollector diagnostics = new DiagnosticCollector<>(); + StandardJavaFileManager fileManager = compiler.getStandardFileManager(diagnostics, null, null); + Iterable units = fileManager.getJavaFileObjectsFromFiles( + Arrays.asList(srcDir.resolve("sample/SampleService.java").toFile()) + ); + + List options = Arrays.asList( + "-d", classesDir.toString(), + "-classpath", System.getProperty("java.class.path") + ); + + Boolean result = compiler.getTask(null, fileManager, diagnostics, options, null, units).call(); + fileManager.close(); + + if (result == null || !result) { + StringBuilder sb = new StringBuilder("Compilation failed:\n"); + for (Diagnostic diagnostic : diagnostics.getDiagnostics()) { + sb.append(diagnostic.getKind()).append(": ") + .append(diagnostic.getMessage(null)).append("\n"); + } + throw new IllegalStateException(sb.toString()); + } + } + + private int findLine(StackTraceElement[] stack, String className, String methodName) { + for (StackTraceElement element : stack) { + if (className.equals(element.getClassName()) && methodName.equals(element.getMethodName())) { + return element.getLineNumber(); + } + } + return -1; + } +} diff --git a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonRepository.java b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonRepository.java index d013547..a0111d1 100644 --- a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonRepository.java +++ b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonRepository.java @@ -1,11 +1,11 @@ package com.example.kolobok; import org.kolobok.annotation.FindWithOptionalParams; -import org.springframework.data.repository.CrudRepository; +import org.springframework.data.jpa.repository.JpaRepository; import java.util.List; -public interface PersonRepository extends CrudRepository { +public interface PersonRepository extends JpaRepository { @FindWithOptionalParams List findByFirstNameAndLastName(String firstName, String lastName); diff --git a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java index 6d4730d..9ac54fa 100644 --- a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java +++ b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java @@ -3,6 +3,8 @@ import io.swagger.v3.oas.annotations.Operation; import io.swagger.v3.oas.annotations.Parameter; import io.swagger.v3.oas.annotations.tags.Tag; +import lombok.extern.slf4j.Slf4j; +import org.kolobok.annotation.LogContext; import org.springframework.http.HttpStatus; import org.springframework.http.ResponseEntity; import org.springframework.web.bind.annotation.*; @@ -12,6 +14,7 @@ @RestController @RequestMapping("/persons") @Tag(name = "Persons", description = "CRUD operations for persons") +@Slf4j public class PersonController { private final PersonService service; @@ -55,11 +58,15 @@ public ResponseEntity delete(@Parameter(description = "Person id") @PathVa @Operation(summary = "Search persons by optional firstName/lastName") @GetMapping("/search") + @LogContext public List search( @Parameter(description = "First name") @RequestParam(required = false) String firstName, @Parameter(description = "Last name") @RequestParam(required = false) String lastName, @Parameter(description = "Title") @RequestParam(required = false) String title ) { + if("error".equals(firstName)) { + throw new RuntimeException("Simulated error"); + } return service.search(firstName, lastName, title); } } diff --git a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonRepository.java b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonRepository.java index 5a83aca..a01f879 100644 --- a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonRepository.java +++ b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonRepository.java @@ -1,11 +1,11 @@ package com.example.kolobok; import org.kolobok.annotation.FindWithOptionalParams; -import org.springframework.data.repository.CrudRepository; +import org.springframework.data.jpa.repository.JpaRepository; import java.util.List; -public interface PersonRepository extends CrudRepository { +public interface PersonRepository extends JpaRepository { @FindWithOptionalParams List findByFirstNameAndLastName(String firstName, String lastName); @FindWithOptionalParams From 5720a51aa31dbba5fef32b2cf5a3dc7e7507e3f9 Mon Sep 17 00:00:00 2001 From: Sergey Grigorchuk Date: Thu, 22 Jan 2026 12:24:51 +0000 Subject: [PATCH 2/3] Context Log format Imrpovements --- README.md | 45 +- .../org/kolobok/annotation/LogContext.java | 25 + .../org/kolobok/runtime/LogContextTrace.java | 474 +++++++++++ .../transformer/KolobokTransformer.java | 780 ++++++++++++++++-- .../LogContextHeatMapIntegrationTest.java | 122 +++ 5 files changed, 1377 insertions(+), 69 deletions(-) create mode 100644 kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java create mode 100644 kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java diff --git a/README.md b/README.md index 460fc99..a7432d3 100644 --- a/README.md +++ b/README.md @@ -72,7 +72,21 @@ Also it generates default implementation of `findByFirstNameAndLastNameAndCityId ``` ## @LogContext -`@LogContext` logs method entry (arguments), return values, exceptions, and execution time using an existing logger field on the class. The transformer looks for a static logger field named `log`, `logger`, `LOG`, or `LOGGER` with type `org.slf4j.Logger`. Entry/exit logs are emitted at `debug`, exceptions at `error`. +`@LogContext` logs method entry (arguments), return values, exceptions, and execution time using an existing logger field on the class. The transformer looks for a static logger field named `log`, `logger`, `LOG`, or `LOGGER` with type `org.slf4j.Logger`. Entry/exit/heat map logs are emitted at `logLevel` (default: `DEBUG`), exceptions at `error`. + +Optional flags: +- `lineHeatMap` collects per-line hit counts and logs a compressed JSON heat map after method exit. +- `lineHeatMapOnException` logs the heat map only when the method throws. +- `subHeatMap` suppresses top-level output when there is no parent heat map. +- `logDuration` adds `durationNs` to the heat map JSON. +- `aggregateChildren` collapses repeated child methods into one node (default: true). +- `logArgs` toggles argument logging (default: true). +- `mask` hides selected arguments by index (e.g. `"0,2-3"` or `"*"`). +- `maxArgLength` caps stringified arguments (default: 200). +- `logLevel` controls log level for entry/exit/heat map (`TRACE`, `DEBUG`, `INFO`, `WARN`, `ERROR`). +- `logFormat` controls log format for entry/exit/heat map (`HUMAN` or `JSON`, default: `HUMAN`). +- `logThreadId` adds `threadId` (default: false). +- `logThreadName` adds `threadName` (default: false). ```java import org.kolobok.annotation.LogContext; @@ -82,15 +96,40 @@ import org.slf4j.LoggerFactory; public class SampleService { private static final Logger log = LoggerFactory.getLogger(SampleService.class); - @LogContext + @LogContext(lineHeatMap = true, logDuration = true) public String work(String name, int count) { return name + count; } } + +Heat map output format: +```json +{ + "traceId": "b9ce1b1e-23a3-4a4f-9f0b-78e8c78d82aa", + "method": "com.example.Foo#bar(Ljava/lang/String;I)Ljava/lang/String;", + "count": 1, + "arguments": ["val1", 2], + "lineHeatMap": { + "100-103": 1, + "104": 10 + }, + "durationNs": 123456, + "children": [] +} +``` + +Human log examples: +``` +[LC] ENTER com.example.Foo#bar(String, int):String trace=... t=32 tn=http-nio-8080-exec-1 args=["val1", 2] +[LC] EXIT com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns result=ok +[LC] ERROR com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns err=IllegalStateException:boom +[LC] HEATMAP com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns args=["val1", 2] heatmap={100-103:1,104:10} + - com.example.Foo#child(String):void count=2 dur=4000ns args=["x"] heatmap={120:2} +``` ``` ## How to use Kolobok? -Kolobok uses a bytecode transformer after compilation, so no special compiler flags are needed. It works on Java 11 and newer (verified on 11, 17, 21, 25). +Kolobok uses a bytecode transformer after compilation, so no special compiler flags are needed. It works on Java 11 and newer (verified on 11, 17, 21, 25). If you enable `@LogContext` heat maps, ensure the `kolobok` jar is available at runtime (do not use `provided`/`compileOnly`). Maven: ```xml diff --git a/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java b/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java index bd4f895..8367763 100644 --- a/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java +++ b/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java @@ -8,4 +8,29 @@ @Retention(RetentionPolicy.CLASS) @Target({ElementType.TYPE, ElementType.METHOD}) public @interface LogContext { + boolean lineHeatMap() default false; + boolean lineHeatMapOnException() default false; + boolean subHeatMap() default false; + boolean logDuration() default false; + boolean aggregateChildren() default true; + boolean logArgs() default true; + String mask() default ""; + int maxArgLength() default 200; + LogLevel logLevel() default LogLevel.DEBUG; + LogFormat logFormat() default LogFormat.HUMAN; + boolean logThreadId() default false; + boolean logThreadName() default false; + + enum LogLevel { + TRACE, + DEBUG, + INFO, + WARN, + ERROR + } + + enum LogFormat { + HUMAN, + JSON + } } diff --git a/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java b/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java new file mode 100644 index 0000000..11544bf --- /dev/null +++ b/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java @@ -0,0 +1,474 @@ +package org.kolobok.runtime; + +import java.lang.reflect.Method; +import java.util.ArrayDeque; +import java.util.ArrayList; +import java.util.Deque; +import java.util.List; +import java.util.UUID; + +public final class LogContextTrace { + private static final ThreadLocal TRACE = new ThreadLocal<>(); + + private LogContextTrace() { + } + + public static Object enter(String method, boolean subHeatMap, boolean aggregateChildren, boolean logArgs, + String mask, int maxArgLength, Object[] args) { + TraceState state = TRACE.get(); + if (state == null) { + state = new TraceState(resolveTraceId(), subHeatMap, aggregateChildren); + TRACE.set(state); + } + TraceNode node = new TraceNode(method); + node.arguments = sanitizeArgs(args, logArgs, mask, maxArgLength); + if (!state.stack.isEmpty()) { + state.stack.peek().children.add(node); + } + state.stack.push(node); + return node; + } + + public static Object enter(String method, boolean subHeatMap, boolean aggregateChildren, Object[] args) { + return enter(method, subHeatMap, aggregateChildren, true, "", 200, args); + } + + public static String exit(Object token, int[] lines, int[] counts, long durationNs, boolean logOnException, boolean isException) { + TraceResult result = exitInternal(token, lines, counts, durationNs, logOnException, isException); + if (result == null) { + return null; + } + if (result.aggregateChildren) { + aggregateNode(result.node); + } + return buildJson(result.traceId, result.node); + } + + public static String exitFormatted(Object token, int[] lines, int[] counts, long durationNs, + boolean logOnException, boolean isException, boolean jsonFormat, + boolean logThreadId, boolean logThreadName) { + TraceResult result = exitInternal(token, lines, counts, durationNs, logOnException, isException); + if (result == null) { + return null; + } + if (result.aggregateChildren) { + aggregateNode(result.node); + } + if (jsonFormat) { + return buildJson(result.traceId, result.node); + } + return buildHumanHeatMap(result.traceId, result.node, logThreadId, logThreadName); + } + + private static String buildJson(String traceId, TraceNode node) { + StringBuilder sb = new StringBuilder(); + sb.append("{\"traceId\":\"").append(escapeJson(traceId)).append("\","); + appendNodeJson(sb, node); + sb.append('}'); + return sb.toString(); + } + + private static void appendNodeJson(StringBuilder sb, TraceNode node) { + sb.append("\"method\":\"").append(escapeJson(node.method)).append("\","); + sb.append("\"count\":").append(node.count).append(','); + if (node.arguments != null) { + sb.append("\"arguments\":["); + for (int i = 0; i < node.arguments.length; i++) { + if (i > 0) { + sb.append(','); + } + sb.append(toJsonValue(node.arguments[i])); + } + sb.append("],"); + } + sb.append("\"lineHeatMap\":{"); + if (node.lineCounts != null && !node.lineCounts.isEmpty()) { + sb.append(compressLineCounts(node.lineCounts)); + } + sb.append("},"); + if (node.durationNs >= 0) { + sb.append("\"durationNs\":").append(node.durationNs).append(','); + } + sb.append("\"children\":["); + for (int i = 0; i < node.children.size(); i++) { + if (i > 0) { + sb.append(','); + } + sb.append('{'); + appendNodeJson(sb, node.children.get(i)); + sb.append('}'); + } + sb.append(']'); + } + + public static String currentTraceId() { + TraceState state = TRACE.get(); + if (state != null) { + return state.traceId; + } + return resolveFromMdc(); + } + + public static String formatTraceIdHuman() { + String traceId = currentTraceId(); + if (traceId == null || traceId.isEmpty()) { + return ""; + } + return " trace=" + traceId; + } + + public static String formatTraceIdJson() { + String traceId = currentTraceId(); + if (traceId == null || traceId.isEmpty()) { + return ""; + } + return ",\"traceId\":\"" + escapeJson(traceId) + "\""; + } + + private static String resolveTraceId() { + String traceId = resolveFromMdc(); + return (traceId == null || traceId.isEmpty()) ? UUID.randomUUID().toString() : traceId; + } + + private static String resolveFromMdc() { + try { + Class mdcClass = Class.forName("org.slf4j.MDC"); + Method get = mdcClass.getMethod("get", String.class); + Object value = get.invoke(null, "traceId"); + return value == null ? null : value.toString(); + } catch (ReflectiveOperationException ignored) { + return null; + } + } + + public static String escapeJson(String value) { + if (value == null) { + return "null"; + } + StringBuilder sb = new StringBuilder(value.length() + 8); + for (int i = 0; i < value.length(); i++) { + char c = value.charAt(i); + if (c == '"' || c == '\\') { + sb.append('\\'); + } + sb.append(c); + } + return sb.toString(); + } + + private static String toJsonValue(Object value) { + if (value == null) { + return "null"; + } + if (value instanceof Number || value instanceof Boolean) { + return value.toString(); + } + return "\"" + escapeJson(value.toString()) + "\""; + } + + public static String formatArgs(Object[] args, String mask, int maxArgLength) { + Object[] sanitized = sanitizeArgs(args, true, mask, maxArgLength); + if (sanitized == null) { + return "[]"; + } + return java.util.Arrays.deepToString(sanitized); + } + + public static String formatArgsJson(Object[] args, String mask, int maxArgLength) { + Object[] sanitized = sanitizeArgs(args, true, mask, maxArgLength); + if (sanitized == null) { + return "[]"; + } + StringBuilder sb = new StringBuilder(); + sb.append('['); + for (int i = 0; i < sanitized.length; i++) { + if (i > 0) { + sb.append(','); + } + sb.append(toJsonValue(sanitized[i])); + } + sb.append(']'); + return sb.toString(); + } + + private static final class TraceState { + private final String traceId; + private final boolean suppressedRoot; + private final boolean aggregateChildren; + private final Deque stack = new ArrayDeque<>(); + + private TraceState(String traceId, boolean suppressedRoot, boolean aggregateChildren) { + this.traceId = traceId; + this.suppressedRoot = suppressedRoot; + this.aggregateChildren = aggregateChildren; + } + } + + private static final class TraceNode { + private final String method; + private final List children = new ArrayList<>(); + private int count; + private java.util.Map lineCounts; + private long durationNs = -1; + private Object[] arguments; + + private TraceNode(String method) { + this.method = method; + } + } + + private static java.util.Map buildLineCounts(int[] lines, int[] counts) { + if (lines == null || counts == null || lines.length != counts.length) { + return java.util.Collections.emptyMap(); + } + java.util.Map map = new java.util.HashMap<>(); + for (int i = 0; i < lines.length; i++) { + int count = counts[i]; + if (count != 0) { + map.put(lines[i], count); + } + } + return map; + } + + private static String compressLineCounts(java.util.Map counts) { + java.util.List lines = new java.util.ArrayList<>(counts.keySet()); + java.util.Collections.sort(lines); + StringBuilder sb = new StringBuilder(); + int i = 0; + while (i < lines.size()) { + int start = lines.get(i); + int end = start; + int value = counts.get(start); + int j = i + 1; + while (j < lines.size()) { + int next = lines.get(j); + if (next != end + 1 || counts.get(next) != value) { + break; + } + end = next; + j++; + } + if (sb.length() > 0) { + sb.append(", "); + } + sb.append('"').append(start); + if (end != start) { + sb.append('-').append(end); + } + sb.append("\":").append(value); + i = j; + } + return sb.toString(); + } + + private static String buildHumanHeatMap(String traceId, TraceNode node, boolean logThreadId, boolean logThreadName) { + StringBuilder sb = new StringBuilder(); + appendHumanNode(sb, node, 0, traceId, logThreadId, logThreadName); + return sb.toString(); + } + + private static void appendHumanNode(StringBuilder sb, TraceNode node, int depth, String traceId, + boolean logThreadId, boolean logThreadName) { + if (depth == 0) { + sb.append("[LC] HEATMAP "); + } else { + for (int i = 0; i < depth; i++) { + sb.append(" "); + } + sb.append("- "); + } + sb.append(node.method); + if (depth == 0 && traceId != null && !traceId.isEmpty()) { + sb.append(" trace=").append(traceId); + } + if (depth == 0 && logThreadId) { + sb.append(" t=").append(Thread.currentThread().getId()); + } + if (depth == 0 && logThreadName) { + sb.append(" tn=").append(Thread.currentThread().getName()); + } + sb.append(" count=").append(node.count); + if (node.durationNs >= 0) { + sb.append(" dur=").append(node.durationNs).append("ns"); + } + if (node.arguments != null) { + sb.append(" args=").append(java.util.Arrays.deepToString(node.arguments)); + } + sb.append(" heatmap={"); + if (node.lineCounts != null && !node.lineCounts.isEmpty()) { + sb.append(compressLineCounts(node.lineCounts)); + } + sb.append('}'); + if (!node.children.isEmpty()) { + sb.append('\n'); + for (int i = 0; i < node.children.size(); i++) { + if (i > 0) { + // previous child already added newline + } + appendHumanNode(sb, node.children.get(i), depth + 1, traceId, logThreadId, logThreadName); + if (i < node.children.size() - 1) { + sb.append('\n'); + } + } + } + } + + private static Object[] sanitizeArgs(Object[] args, boolean logArgs, String mask, int maxArgLength) { + if (!logArgs) { + return null; + } + Object[] safeArgs = args == null ? new Object[0] : args; + if (safeArgs.length == 0) { + return safeArgs; + } + MaskSpec maskSpec = parseMask(mask); + int limit = maxArgLength > 0 ? maxArgLength : 200; + Object[] sanitized = new Object[safeArgs.length]; + for (int i = 0; i < safeArgs.length; i++) { + if (maskSpec.maskAll || maskSpec.indexes.contains(i)) { + sanitized[i] = "***"; + continue; + } + Object arg = safeArgs[i]; + if (arg == null || arg instanceof Number || arg instanceof Boolean) { + sanitized[i] = arg; + continue; + } + String value = String.valueOf(arg); + sanitized[i] = truncate(value, limit); + } + return sanitized; + } + + private static String truncate(String value, int limit) { + if (value == null || value.length() <= limit) { + return value; + } + return value.substring(0, limit) + "..."; + } + + private static MaskSpec parseMask(String mask) { + MaskSpec spec = new MaskSpec(); + if (mask == null) { + return spec; + } + String trimmed = mask.trim(); + if (trimmed.isEmpty()) { + return spec; + } + if ("*".equals(trimmed)) { + spec.maskAll = true; + return spec; + } + String[] parts = trimmed.split(","); + for (String part : parts) { + String token = part.trim(); + if (token.isEmpty()) { + continue; + } + int dash = token.indexOf('-'); + if (dash > 0) { + try { + int start = Integer.parseInt(token.substring(0, dash).trim()); + int end = Integer.parseInt(token.substring(dash + 1).trim()); + if (start > end) { + int tmp = start; + start = end; + end = tmp; + } + for (int i = start; i <= end; i++) { + spec.indexes.add(i); + } + } catch (NumberFormatException ignored) { + continue; + } + } else { + try { + spec.indexes.add(Integer.parseInt(token)); + } catch (NumberFormatException ignored) { + continue; + } + } + } + return spec; + } + + private static void aggregateNode(TraceNode node) { + java.util.Map aggregated = new java.util.LinkedHashMap<>(); + for (TraceNode child : node.children) { + TraceNode existing = aggregated.get(child.method); + if (existing == null) { + aggregated.put(child.method, child); + } else { + existing.count += child.count; + existing.durationNs += child.durationNs; + mergeLineCounts(existing.lineCounts, child.lineCounts); + existing.children.addAll(child.children); + if (existing.count > 1) { + existing.arguments = null; + } + } + } + node.children.clear(); + for (TraceNode child : aggregated.values()) { + if (!child.children.isEmpty()) { + aggregateNode(child); + } + node.children.add(child); + } + } + + private static void mergeLineCounts(java.util.Map target, java.util.Map source) { + if (target == null || source == null) { + return; + } + for (java.util.Map.Entry entry : source.entrySet()) { + target.merge(entry.getKey(), entry.getValue(), Integer::sum); + } + } + + private static TraceResult exitInternal(Object token, int[] lines, int[] counts, long durationNs, + boolean logOnException, boolean isException) { + TraceState state = TRACE.get(); + if (state == null) { + return null; + } + TraceNode node = (TraceNode) token; + node.lineCounts = buildLineCounts(lines, counts); + node.durationNs = durationNs; + node.count = 1; + state.stack.pop(); + + if (!state.stack.isEmpty()) { + return null; + } + + TRACE.remove(); + + if (state.suppressedRoot) { + return null; + } + if (logOnException && !isException) { + return null; + } + return new TraceResult(state.traceId, node, state.aggregateChildren); + } + + private static final class TraceResult { + private final String traceId; + private final TraceNode node; + private final boolean aggregateChildren; + + private TraceResult(String traceId, TraceNode node, boolean aggregateChildren) { + this.traceId = traceId; + this.node = node; + this.aggregateChildren = aggregateChildren; + } + } + + private static final class MaskSpec { + private final java.util.Set indexes = new java.util.HashSet<>(); + private boolean maskAll; + } +} diff --git a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java index 6e88f0b..4c7f26a 100644 --- a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java +++ b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java @@ -17,6 +17,7 @@ import org.objectweb.asm.tree.JumpInsnNode; import org.objectweb.asm.tree.LabelNode; import org.objectweb.asm.tree.LdcInsnNode; +import org.objectweb.asm.tree.LineNumberNode; import org.objectweb.asm.tree.MethodInsnNode; import org.objectweb.asm.tree.MethodNode; import org.objectweb.asm.tree.TryCatchBlockNode; @@ -27,8 +28,11 @@ import java.nio.file.Files; import java.nio.file.Path; import java.util.ArrayList; +import java.util.Collections; +import java.util.HashMap; import java.util.HashSet; import java.util.List; +import java.util.Map; import java.util.Set; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -115,13 +119,16 @@ private boolean transformInterface(ClassNode classNode) { } private boolean transformLogContext(ClassNode classNode) { - boolean classAnnotated = hasAnnotation(classNode.visibleAnnotations, LOG_CONTEXT_DESC) - || hasAnnotation(classNode.invisibleAnnotations, LOG_CONTEXT_DESC); + AnnotationNode classAnnotation = findAnnotation(classNode.visibleAnnotations, LOG_CONTEXT_DESC); + if (classAnnotation == null) { + classAnnotation = findAnnotation(classNode.invisibleAnnotations, LOG_CONTEXT_DESC); + } - List methodsToInstrument = new ArrayList<>(); + Map methodsToInstrument = new HashMap<>(); for (MethodNode method : classNode.methods) { - if (shouldInstrumentMethod(method, classAnnotated)) { - methodsToInstrument.add(method); + LogContextConfig config = resolveLogContextConfig(method, classAnnotation); + if (config != null && shouldInstrumentMethod(method)) { + methodsToInstrument.put(method, config); } } @@ -135,14 +142,14 @@ private boolean transformLogContext(ClassNode classNode) { + "' uses @LogContext but no static logger field named log/logger/LOG/LOGGER with type org.slf4j.Logger was found"); } - for (MethodNode method : methodsToInstrument) { - instrumentLogContextMethod(classNode, method, loggerField); + for (Map.Entry entry : methodsToInstrument.entrySet()) { + instrumentLogContextMethod(classNode, entry.getKey(), loggerField, entry.getValue()); } return true; } - private boolean shouldInstrumentMethod(MethodNode method, boolean classAnnotated) { + private boolean shouldInstrumentMethod(MethodNode method) { if ((method.access & (Opcodes.ACC_ABSTRACT | Opcodes.ACC_NATIVE)) != 0) { return false; } @@ -152,7 +159,35 @@ private boolean shouldInstrumentMethod(MethodNode method, boolean classAnnotated if (method.instructions == null || method.instructions.size() == 0) { return false; } - return classAnnotated || hasAnnotation(method, LOG_CONTEXT_DESC); + return true; + } + + private LogContextConfig resolveLogContextConfig(MethodNode method, AnnotationNode classAnnotation) { + AnnotationNode methodAnnotation = findAnnotation(method, LOG_CONTEXT_DESC); + if (methodAnnotation == null) { + methodAnnotation = classAnnotation; + } + if (methodAnnotation == null) { + return null; + } + boolean lineHeatMap = getBooleanValue(methodAnnotation, "lineHeatMap", false); + boolean lineHeatMapOnException = getBooleanValue(methodAnnotation, "lineHeatMapOnException", false); + boolean subHeatMap = getBooleanValue(methodAnnotation, "subHeatMap", false); + boolean logDuration = getBooleanValue(methodAnnotation, "logDuration", false); + boolean aggregateChildren = getBooleanValue(methodAnnotation, "aggregateChildren", true); + boolean logArgs = getBooleanValue(methodAnnotation, "logArgs", true); + String mask = getStringValue(methodAnnotation, "mask", ""); + int maxArgLength = getIntValue(methodAnnotation, "maxArgLength", 200); + String logLevelName = getEnumValue(methodAnnotation, "logLevel", "DEBUG"); + String logFormatName = getEnumValue(methodAnnotation, "logFormat", "HUMAN"); + boolean logThreadId = getBooleanValue(methodAnnotation, "logThreadId", false); + boolean logThreadName = getBooleanValue(methodAnnotation, "logThreadName", false); + if (lineHeatMapOnException) { + lineHeatMap = true; + } + return new LogContextConfig(lineHeatMap, lineHeatMapOnException, subHeatMap, logDuration, aggregateChildren, + logArgs, mask, maxArgLength, LogLevelConfig.fromName(logLevelName), + LogFormatConfig.fromName(logFormatName), logThreadId, logThreadName); } private FieldNode findLoggerField(ClassNode classNode) { @@ -172,35 +207,56 @@ private FieldNode findLoggerField(ClassNode classNode) { return null; } - private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, FieldNode loggerField) { + private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, FieldNode loggerField, LogContextConfig config) { boolean isStatic = (method.access & Opcodes.ACC_STATIC) != 0; Type[] argTypes = Type.getArgumentTypes(method.desc); Type returnType = Type.getReturnType(method.desc); int[] argIndexes = computeArgIndexes(isStatic, argTypes); - int startTimeVar = method.maxLocals; - method.maxLocals += 2; + List lineNumbers = config.lineHeatMap ? collectLineNumbers(method.instructions) : Collections.emptyList(); + boolean hasHeatMap = config.lineHeatMap && !lineNumbers.isEmpty(); + + int nextLocal = method.maxLocals; + int linesVar = -1; + int countsVar = -1; + int traceVar = -1; + if (hasHeatMap) { + linesVar = nextLocal++; + countsVar = nextLocal++; + traceVar = nextLocal++; + } + + int startTimeVar = nextLocal; + nextLocal += 2; int returnVar = -1; if (returnType.getSort() != Type.VOID) { - returnVar = method.maxLocals; - method.maxLocals += returnType.getSize(); + returnVar = nextLocal; + nextLocal += returnType.getSize(); } - int durationVar = method.maxLocals; - method.maxLocals += 2; + int durationVar = nextLocal; + nextLocal += 2; + + int exceptionVar = nextLocal; + nextLocal += 1; - int exceptionVar = method.maxLocals; - method.maxLocals += 1; + method.maxLocals = nextLocal; LabelNode startLabel = new LabelNode(); LabelNode endLabel = new LabelNode(); LabelNode handlerLabel = new LabelNode(); InsnList entry = new InsnList(); + if (hasHeatMap) { + append(entry, buildLineArrayInit(lineNumbers, linesVar, countsVar)); + insertLineCounters(method, lineNumbers, countsVar); + append(entry, buildTraceEnter(classNode, method, traceVar, config.subHeatMap, config.aggregateChildren, + config.logArgs, config.mask, config.maxArgLength, config.logFormat, argTypes, argIndexes)); + } entry.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); entry.add(new VarInsnNode(Opcodes.LSTORE, startTimeVar)); - append(entry, buildEntryLog(classNode, method, loggerField, argTypes, argIndexes)); + append(entry, buildEntryLog(classNode, method, loggerField, config, argTypes, argIndexes)); entry.add(startLabel); method.instructions.insert(entry); @@ -216,11 +272,17 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, InsnList exit = new InsnList(); int opcode = ret.getOpcode(); if (returnType.getSort() == Type.VOID) { - append(exit, buildExitLog(classNode, method, loggerField, startTimeVar, durationVar, null, null)); + append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, null, null)); + if (hasHeatMap) { + append(exit, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, false)); + } exit.add(new InsnNode(Opcodes.RETURN)); } else { exit.add(new VarInsnNode(returnType.getOpcode(Opcodes.ISTORE), returnVar)); - append(exit, buildExitLog(classNode, method, loggerField, startTimeVar, durationVar, returnType, returnVar)); + append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, returnType, returnVar)); + if (hasHeatMap) { + append(exit, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, false)); + } exit.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); exit.add(new InsnNode(opcode)); } @@ -232,7 +294,10 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, handler.add(endLabel); handler.add(handlerLabel); handler.add(new VarInsnNode(Opcodes.ASTORE, exceptionVar)); - append(handler, buildErrorLog(classNode, method, loggerField, startTimeVar, durationVar, exceptionVar)); + append(handler, buildErrorLog(classNode, method, loggerField, config, startTimeVar, durationVar, exceptionVar)); + if (hasHeatMap) { + append(handler, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, true)); + } handler.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); handler.add(new InsnNode(Opcodes.ATHROW)); method.instructions.add(handler); @@ -241,33 +306,77 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, } private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode loggerField, - Type[] argTypes, int[] argIndexes) { + LogContextConfig config, Type[] argTypes, int[] argIndexes) { InsnList insns = new InsnList(); LabelNode skipLabel = new LabelNode(); insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); - insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "isDebugEnabled", "()Z", true)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.isEnabledMethod, + "()Z", true)); insns.add(new JumpInsnNode(Opcodes.IFEQ, skipLabel)); - append(insns, buildArgsArray(argTypes, argIndexes)); - insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/util/Arrays", "deepToString", - "([Ljava/lang/Object;)Ljava/lang/String;", false)); - - String prefix = "Enter " + toHumanName(classNode.name) + "#" + method.name + " args="; + String methodDisplay = buildMethodDisplayName(classNode, method, config.logFormat); insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); insns.add(new InsnNode(Opcodes.DUP)); - insns.add(new LdcInsnNode(prefix)); + if (config.logFormat.jsonFormat) { + insns.add(new LdcInsnNode("{\"type\":\"enter\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); + } else { + insns.add(new LdcInsnNode("[LC] ENTER " + methodDisplay)); + } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); - insns.add(new InsnNode(Opcodes.SWAP)); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + + if (config.logFormat.jsonFormat) { + append(insns, buildTraceIdAppendJson()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendJson()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendJson()); + } + if (config.logArgs) { + insns.add(new LdcInsnNode(",\"args\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + append(insns, buildArgsArray(argTypes, argIndexes)); + insns.add(new LdcInsnNode(config.mask)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgsJson", + "([Ljava/lang/Object;Ljava/lang/String;I)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + insns.add(new LdcInsnNode("}")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } else { + append(insns, buildTraceIdAppendHuman()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendHuman()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendHuman()); + } + if (config.logArgs) { + insns.add(new LdcInsnNode(" args=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + append(insns, buildArgsArray(argTypes, argIndexes)); + insns.add(new LdcInsnNode(config.mask)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgs", + "([Ljava/lang/Object;Ljava/lang/String;I)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + } + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", "()Ljava/lang/String;", false)); insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); insns.add(new InsnNode(Opcodes.SWAP)); - insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "debug", + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.logMethod, "(Ljava/lang/String;)V", true)); insns.add(skipLabel); @@ -275,12 +384,14 @@ private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode } private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode loggerField, - int startTimeVar, int durationVar, Type returnType, Integer returnVar) { + LogContextConfig config, int startTimeVar, int durationVar, + Type returnType, Integer returnVar) { InsnList insns = new InsnList(); LabelNode skipLabel = new LabelNode(); insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); - insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "isDebugEnabled", "()Z", true)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.isEnabledMethod, + "()Z", true)); insns.add(new JumpInsnNode(Opcodes.IFEQ, skipLabel)); insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); @@ -288,39 +399,83 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new InsnNode(Opcodes.LSUB)); insns.add(new VarInsnNode(Opcodes.LSTORE, durationVar)); - String prefix = "Exit " + toHumanName(classNode.name) + "#" + method.name + " result="; + String methodDisplay = buildMethodDisplayName(classNode, method, config.logFormat); insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); insns.add(new InsnNode(Opcodes.DUP)); - insns.add(new LdcInsnNode(prefix)); + if (config.logFormat.jsonFormat) { + insns.add(new LdcInsnNode("{\"type\":\"exit\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); + } else { + insns.add(new LdcInsnNode("[LC] EXIT " + methodDisplay)); + } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); - if (returnType == null) { - insns.add(new LdcInsnNode("void")); + if (config.logFormat.jsonFormat) { + append(insns, buildTraceIdAppendJson()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendJson()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendJson()); + } + insns.add(new LdcInsnNode(",\"durationNs\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode(",\"result\":\"")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + if (returnType == null) { + insns.add(new LdcInsnNode("void")); + } else { + insns.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); + boxValue(insns, returnType); + } + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", + "(Ljava/lang/Object;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "escapeJson", + "(Ljava/lang/String;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("\"}")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); } else { - insns.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); - boxValue(insns, returnType); + append(insns, buildTraceIdAppendHuman()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendHuman()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendHuman()); + } + insns.add(new LdcInsnNode(" dur=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("ns result=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + if (returnType == null) { + insns.add(new LdcInsnNode("void")); + } else { + insns.add(new VarInsnNode(returnType.getOpcode(Opcodes.ILOAD), returnVar)); + boxValue(insns, returnType); + } + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", + "(Ljava/lang/Object;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); } - insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", - "(Ljava/lang/Object;)Ljava/lang/String;", false)); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); - - insns.add(new LdcInsnNode(" took=")); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); - insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(J)Ljava/lang/StringBuilder;", false)); - insns.add(new LdcInsnNode("ns")); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", "()Ljava/lang/String;", false)); insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); insns.add(new InsnNode(Opcodes.SWAP)); - insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", "debug", + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.logMethod, "(Ljava/lang/String;)V", true)); insns.add(skipLabel); @@ -328,25 +483,75 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode } private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode loggerField, - int startTimeVar, int durationVar, int exceptionVar) { + LogContextConfig config, int startTimeVar, int durationVar, int exceptionVar) { InsnList insns = new InsnList(); insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); insns.add(new VarInsnNode(Opcodes.LLOAD, startTimeVar)); insns.add(new InsnNode(Opcodes.LSUB)); insns.add(new VarInsnNode(Opcodes.LSTORE, durationVar)); - String prefix = "Error " + toHumanName(classNode.name) + "#" + method.name + " took="; + String methodDisplay = buildMethodDisplayName(classNode, method, config.logFormat); insns.add(new TypeInsnNode(Opcodes.NEW, "java/lang/StringBuilder")); insns.add(new InsnNode(Opcodes.DUP)); - insns.add(new LdcInsnNode(prefix)); + if (config.logFormat.jsonFormat) { + insns.add(new LdcInsnNode("{\"type\":\"error\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); + } else { + insns.add(new LdcInsnNode("[LC] ERROR " + methodDisplay)); + } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); - insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(J)Ljava/lang/StringBuilder;", false)); - insns.add(new LdcInsnNode("ns")); - insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", - "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + + if (config.logFormat.jsonFormat) { + append(insns, buildTraceIdAppendJson()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendJson()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendJson()); + } + insns.add(new LdcInsnNode(",\"durationNs\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode(",\"error\":\"")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", + "(Ljava/lang/Object;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "escapeJson", + "(Ljava/lang/String;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("\"}")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } else { + append(insns, buildTraceIdAppendHuman()); + if (config.logThreadId) { + append(insns, buildThreadIdAppendHuman()); + } + if (config.logThreadName) { + append(insns, buildThreadNameAppendHuman()); + } + insns.add(new LdcInsnNode(" dur=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("ns err=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/String", "valueOf", + "(Ljava/lang/Object;)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", "()Ljava/lang/String;", false)); @@ -358,6 +563,139 @@ private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode return insns; } + private InsnList buildHeatMapLog(ClassNode classNode, MethodNode method, FieldNode loggerField, + int linesVar, int countsVar, int traceVar, LogContextConfig config, + int durationVar, boolean isException) { + InsnList insns = new InsnList(); + insns.add(new VarInsnNode(Opcodes.ALOAD, traceVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, linesVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, countsVar)); + + if (config.logDuration) { + insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); + } else { + insns.add(new LdcInsnNode(-1L)); + } + insns.add(new LdcInsnNode(config.lineHeatMapOnException)); + insns.add(new LdcInsnNode(isException)); + insns.add(new LdcInsnNode(config.logFormat.jsonFormat)); + insns.add(new LdcInsnNode(config.logThreadId)); + insns.add(new LdcInsnNode(config.logThreadName)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "exitFormatted", + "(Ljava/lang/Object;[I[IJZZZZZ)Ljava/lang/String;", false)); + + LabelNode skipNull = new LabelNode(); + LabelNode skipLog = new LabelNode(); + LabelNode done = new LabelNode(); + insns.add(new InsnNode(Opcodes.DUP)); + insns.add(new JumpInsnNode(Opcodes.IFNULL, skipNull)); + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.isEnabledMethod, + "()Z", true)); + insns.add(new JumpInsnNode(Opcodes.IFEQ, skipLog)); + insns.add(new FieldInsnNode(Opcodes.GETSTATIC, classNode.name, loggerField.name, loggerField.desc)); + insns.add(new InsnNode(Opcodes.SWAP)); + insns.add(new MethodInsnNode(Opcodes.INVOKEINTERFACE, "org/slf4j/Logger", config.logLevel.logMethod, + "(Ljava/lang/String;)V", true)); + insns.add(new JumpInsnNode(Opcodes.GOTO, done)); + insns.add(skipLog); + insns.add(new InsnNode(Opcodes.POP)); + insns.add(new JumpInsnNode(Opcodes.GOTO, done)); + insns.add(skipNull); + insns.add(new InsnNode(Opcodes.POP)); + insns.add(done); + return insns; + } + + private InsnList buildLineArrayInit(List lineNumbers, int linesVar, int countsVar) { + InsnList insns = new InsnList(); + pushInt(insns, lineNumbers.size()); + insns.add(new IntInsnNode(Opcodes.NEWARRAY, Opcodes.T_INT)); + for (int i = 0; i < lineNumbers.size(); i++) { + insns.add(new InsnNode(Opcodes.DUP)); + pushInt(insns, i); + insns.add(new LdcInsnNode(lineNumbers.get(i))); + insns.add(new InsnNode(Opcodes.IASTORE)); + } + insns.add(new VarInsnNode(Opcodes.ASTORE, linesVar)); + + pushInt(insns, lineNumbers.size()); + insns.add(new IntInsnNode(Opcodes.NEWARRAY, Opcodes.T_INT)); + insns.add(new VarInsnNode(Opcodes.ASTORE, countsVar)); + return insns; + } + + private void insertLineCounters(MethodNode method, List lineNumbers, int countsVar) { + Map indexByLine = new HashMap<>(); + for (int i = 0; i < lineNumbers.size(); i++) { + indexByLine.put(lineNumbers.get(i), i); + } + + for (AbstractInsnNode insn = method.instructions.getFirst(); insn != null; insn = insn.getNext()) { + if (!(insn instanceof LineNumberNode)) { + continue; + } + LineNumberNode lineNode = (LineNumberNode) insn; + Integer idx = indexByLine.get(lineNode.line); + if (idx == null) { + continue; + } + InsnList inc = new InsnList(); + inc.add(new VarInsnNode(Opcodes.ALOAD, countsVar)); + pushInt(inc, idx); + inc.add(new InsnNode(Opcodes.DUP2)); + inc.add(new InsnNode(Opcodes.IALOAD)); + inc.add(new InsnNode(Opcodes.ICONST_1)); + inc.add(new InsnNode(Opcodes.IADD)); + inc.add(new InsnNode(Opcodes.IASTORE)); + method.instructions.insert(lineNode, inc); + } + } + + private InsnList buildTraceEnter(ClassNode classNode, MethodNode method, int traceVar, boolean subHeatMap, + boolean aggregateChildren, boolean logArgs, String mask, int maxArgLength, + LogFormatConfig logFormat, Type[] argTypes, int[] argIndexes) { + InsnList insns = new InsnList(); + String methodDescriptor = logFormat.jsonFormat + ? buildMethodDescriptor(classNode, method) + : buildShortMethodDescriptor(classNode, method); + insns.add(new LdcInsnNode(methodDescriptor)); + insns.add(new LdcInsnNode(subHeatMap)); + insns.add(new LdcInsnNode(aggregateChildren)); + insns.add(new LdcInsnNode(logArgs)); + insns.add(new LdcInsnNode(mask)); + insns.add(new LdcInsnNode(maxArgLength)); + if (logArgs) { + append(insns, buildArgsArray(argTypes, argIndexes)); + } else { + insns.add(new InsnNode(Opcodes.ACONST_NULL)); + } + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "enter", + "(Ljava/lang/String;ZZZLjava/lang/String;I[Ljava/lang/Object;)Ljava/lang/Object;", false)); + insns.add(new VarInsnNode(Opcodes.ASTORE, traceVar)); + return insns; + } + + private List collectLineNumbers(InsnList instructions) { + List lines = new ArrayList<>(); + for (AbstractInsnNode insn = instructions.getFirst(); insn != null; insn = insn.getNext()) { + if (insn instanceof LineNumberNode) { + lines.add(((LineNumberNode) insn).line); + } + } + Collections.sort(lines); + List unique = new ArrayList<>(); + Integer last = null; + for (Integer line : lines) { + if (last == null || !last.equals(line)) { + unique.add(line); + last = line; + } + } + return unique; + } + + private InsnList buildArgsArray(Type[] argTypes, int[] argIndexes) { InsnList insns = new InsnList(); pushInt(insns, argTypes.length); @@ -440,6 +778,156 @@ private String toHumanName(String internalName) { return internalName.replace('/', '.'); } + private String buildMethodDescriptor(ClassNode classNode, MethodNode method) { + return toHumanName(classNode.name) + "#" + method.name + method.desc; + } + + private String buildShortMethodDescriptor(ClassNode classNode, MethodNode method) { + StringBuilder sb = new StringBuilder(); + sb.append(toHumanName(classNode.name)).append('#').append(method.name).append('('); + Type[] argTypes = Type.getArgumentTypes(method.desc); + for (int i = 0; i < argTypes.length; i++) { + if (i > 0) { + sb.append(", "); + } + sb.append(shortTypeName(argTypes[i])); + } + sb.append("):").append(shortTypeName(Type.getReturnType(method.desc))); + return sb.toString(); + } + + private String shortTypeName(Type type) { + switch (type.getSort()) { + case Type.VOID: + return "void"; + case Type.BOOLEAN: + return "boolean"; + case Type.BYTE: + return "byte"; + case Type.CHAR: + return "char"; + case Type.SHORT: + return "short"; + case Type.INT: + return "int"; + case Type.FLOAT: + return "float"; + case Type.LONG: + return "long"; + case Type.DOUBLE: + return "double"; + default: + break; + } + String name = type.getClassName(); + int arrayDim = 0; + while (name.endsWith("[]")) { + arrayDim++; + name = name.substring(0, name.length() - 2); + } + int lastDot = Math.max(name.lastIndexOf('.'), name.lastIndexOf('$')); + if (lastDot >= 0) { + name = name.substring(lastDot + 1); + } + StringBuilder sb = new StringBuilder(name); + for (int i = 0; i < arrayDim; i++) { + sb.append("[]"); + } + return sb.toString(); + } + + private String buildMethodDisplayName(ClassNode classNode, MethodNode method, LogFormatConfig logFormat) { + return logFormat.jsonFormat ? buildMethodDescriptor(classNode, method) : buildShortMethodDescriptor(classNode, method); + } + + private String escapeJson(String value) { + if (value == null) { + return "null"; + } + StringBuilder sb = new StringBuilder(value.length() + 8); + for (int i = 0; i < value.length(); i++) { + char c = value.charAt(i); + if (c == '"' || c == '\\') { + sb.append('\\'); + } + sb.append(c); + } + return sb.toString(); + } + + private InsnList buildTraceIdAppendHuman() { + InsnList insns = new InsnList(); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatTraceIdHuman", + "()Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + return insns; + } + + private InsnList buildTraceIdAppendJson() { + InsnList insns = new InsnList(); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatTraceIdJson", + "()Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + return insns; + } + + private InsnList buildThreadIdAppendHuman() { + InsnList insns = new InsnList(); + insns.add(new LdcInsnNode(" t=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", + "()Ljava/lang/Thread;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getId", "()J", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + return insns; + } + + private InsnList buildThreadNameAppendHuman() { + InsnList insns = new InsnList(); + insns.add(new LdcInsnNode(" tn=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", + "()Ljava/lang/Thread;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getName", "()Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + return insns; + } + + private InsnList buildThreadIdAppendJson() { + InsnList insns = new InsnList(); + insns.add(new LdcInsnNode(",\"threadId\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", + "()Ljava/lang/Thread;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getId", "()J", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(J)Ljava/lang/StringBuilder;", false)); + return insns; + } + + private InsnList buildThreadNameAppendJson() { + InsnList insns = new InsnList(); + insns.add(new LdcInsnNode(",\"threadName\":\"")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/Thread", "currentThread", + "()Ljava/lang/Thread;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/Thread", "getName", "()Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("\"")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + return insns; + } + private void append(InsnList target, InsnList source) { for (AbstractInsnNode node : source.toArray()) { target.add(node); @@ -659,6 +1147,81 @@ private boolean hasAnnotation(MethodNode method, String desc) { return false; } + private AnnotationNode findAnnotation(MethodNode method, String desc) { + AnnotationNode annotation = findAnnotation(method.visibleAnnotations, desc); + if (annotation != null) { + return annotation; + } + return findAnnotation(method.invisibleAnnotations, desc); + } + + private boolean getBooleanValue(AnnotationNode annotation, String name, boolean defaultValue) { + if (annotation == null || annotation.values == null) { + return defaultValue; + } + List values = annotation.values; + for (int i = 0; i < values.size() - 1; i += 2) { + if (name.equals(values.get(i))) { + Object value = values.get(i + 1); + if (value instanceof Boolean) { + return (Boolean) value; + } + } + } + return defaultValue; + } + + private String getStringValue(AnnotationNode annotation, String name, String defaultValue) { + if (annotation == null || annotation.values == null) { + return defaultValue; + } + List values = annotation.values; + for (int i = 0; i < values.size() - 1; i += 2) { + if (name.equals(values.get(i))) { + Object value = values.get(i + 1); + if (value instanceof String) { + return (String) value; + } + } + } + return defaultValue; + } + + private int getIntValue(AnnotationNode annotation, String name, int defaultValue) { + if (annotation == null || annotation.values == null) { + return defaultValue; + } + List values = annotation.values; + for (int i = 0; i < values.size() - 1; i += 2) { + if (name.equals(values.get(i))) { + Object value = values.get(i + 1); + if (value instanceof Integer) { + return (Integer) value; + } + } + } + return defaultValue; + } + + private String getEnumValue(AnnotationNode annotation, String name, String defaultValue) { + if (annotation == null || annotation.values == null) { + return defaultValue; + } + List values = annotation.values; + for (int i = 0; i < values.size() - 1; i += 2) { + if (name.equals(values.get(i))) { + Object value = values.get(i + 1); + if (value instanceof String[]) { + String[] enumValue = (String[]) value; + if (enumValue.length == 2) { + return enumValue[1]; + } + } + } + } + return defaultValue; + } + private boolean hasAnnotation(List annotations, String desc) { if (annotations == null) { return false; @@ -671,6 +1234,18 @@ private boolean hasAnnotation(List annotations, String desc) { return false; } + private AnnotationNode findAnnotation(List annotations, String desc) { + if (annotations == null) { + return null; + } + for (AnnotationNode annotation : annotations) { + if (desc.equals(annotation.desc)) { + return annotation; + } + } + return null; + } + private String signature(MethodNode method) { return method.name + method.desc; } @@ -684,4 +1259,77 @@ private ParamInfo(int argIndex, Type type) { this.type = type; } } + + private static class LogContextConfig { + private final boolean lineHeatMap; + private final boolean lineHeatMapOnException; + private final boolean subHeatMap; + private final boolean logDuration; + private final boolean aggregateChildren; + private final boolean logArgs; + private final String mask; + private final int maxArgLength; + private final LogLevelConfig logLevel; + private final LogFormatConfig logFormat; + private final boolean logThreadId; + private final boolean logThreadName; + + private LogContextConfig(boolean lineHeatMap, boolean lineHeatMapOnException, boolean subHeatMap, boolean logDuration, + boolean aggregateChildren, boolean logArgs, String mask, int maxArgLength, + LogLevelConfig logLevel, LogFormatConfig logFormat, + boolean logThreadId, boolean logThreadName) { + this.lineHeatMap = lineHeatMap; + this.lineHeatMapOnException = lineHeatMapOnException; + this.subHeatMap = subHeatMap; + this.logDuration = logDuration; + this.aggregateChildren = aggregateChildren; + this.logArgs = logArgs; + this.mask = mask; + this.maxArgLength = maxArgLength; + this.logLevel = logLevel; + this.logFormat = logFormat; + this.logThreadId = logThreadId; + this.logThreadName = logThreadName; + } + } + + private static final class LogLevelConfig { + private final String name; + private final String isEnabledMethod; + private final String logMethod; + + private LogLevelConfig(String name, String isEnabledMethod, String logMethod) { + this.name = name; + this.isEnabledMethod = isEnabledMethod; + this.logMethod = logMethod; + } + + private static LogLevelConfig fromName(String name) { + if ("TRACE".equalsIgnoreCase(name)) { + return new LogLevelConfig("TRACE", "isTraceEnabled", "trace"); + } + if ("INFO".equalsIgnoreCase(name)) { + return new LogLevelConfig("INFO", "isInfoEnabled", "info"); + } + if ("WARN".equalsIgnoreCase(name)) { + return new LogLevelConfig("WARN", "isWarnEnabled", "warn"); + } + if ("ERROR".equalsIgnoreCase(name)) { + return new LogLevelConfig("ERROR", "isErrorEnabled", "error"); + } + return new LogLevelConfig("DEBUG", "isDebugEnabled", "debug"); + } + } + + private static final class LogFormatConfig { + private final boolean jsonFormat; + + private LogFormatConfig(boolean jsonFormat) { + this.jsonFormat = jsonFormat; + } + + private static LogFormatConfig fromName(String name) { + return new LogFormatConfig("JSON".equalsIgnoreCase(name)); + } + } } diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java new file mode 100644 index 0000000..e506d36 --- /dev/null +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java @@ -0,0 +1,122 @@ +package org.kolobok.transformer; + +import org.junit.Test; +import org.objectweb.asm.ClassReader; +import org.objectweb.asm.tree.ClassNode; +import org.objectweb.asm.tree.MethodInsnNode; +import org.objectweb.asm.tree.MethodNode; + +import javax.tools.Diagnostic; +import javax.tools.DiagnosticCollector; +import javax.tools.JavaCompiler; +import javax.tools.JavaFileObject; +import javax.tools.StandardJavaFileManager; +import javax.tools.ToolProvider; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.List; +import java.util.Optional; + +import static org.assertj.core.api.Assertions.assertThat; + +public class LogContextHeatMapIntegrationTest { + + @Test + public void instrumentsHeatMapHelpers() throws Exception { + Path tempDir = Files.createTempDirectory("kolobok-log-heatmap"); + Path srcDir = tempDir.resolve("src"); + Path classesDir = tempDir.resolve("classes"); + Files.createDirectories(srcDir.resolve("sample")); + Files.createDirectories(classesDir); + + writeSources(srcDir); + compileSources(srcDir, classesDir); + + Path classFile = classesDir.resolve("sample/SampleService.class"); + KolobokTransformer transformer = new KolobokTransformer(); + transformer.transformClassFile(classFile); + + ClassNode classNode = readClassNode(classFile); + MethodNode work = findMethod(classNode, "work", "()V"); + assertThat(work).isNotNull(); + + boolean hasEnter = Arrays.stream(work.instructions.toArray()) + .filter(node -> node instanceof MethodInsnNode) + .map(node -> (MethodInsnNode) node) + .anyMatch(node -> "org/kolobok/runtime/LogContextTrace".equals(node.owner) && "enter".equals(node.name)); + boolean hasExit = Arrays.stream(work.instructions.toArray()) + .filter(node -> node instanceof MethodInsnNode) + .map(node -> (MethodInsnNode) node) + .anyMatch(node -> "org/kolobok/runtime/LogContextTrace".equals(node.owner) && "exitFormatted".equals(node.name)); + assertThat(hasEnter).isTrue(); + assertThat(hasExit).isTrue(); + } + + private void writeSources(Path srcDir) throws IOException { + String service = String.join("\n", + "package sample;", + "", + "import org.kolobok.annotation.LogContext;", + "import org.slf4j.Logger;", + "import org.slf4j.LoggerFactory;", + "", + "public class SampleService {", + " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", + "", + " @LogContext(lineHeatMap = true, logDuration = true)", + " public void work() {", + " if (System.currentTimeMillis() > 0) {", + " return;", + " }", + " }", + "}", + "" + ); + Files.writeString(srcDir.resolve("sample/SampleService.java"), service); + } + + private void compileSources(Path srcDir, Path classesDir) throws IOException { + JavaCompiler compiler = ToolProvider.getSystemJavaCompiler(); + assertThat(compiler).as("System Java compiler is available").isNotNull(); + + DiagnosticCollector diagnostics = new DiagnosticCollector<>(); + StandardJavaFileManager fileManager = compiler.getStandardFileManager(diagnostics, null, null); + Iterable units = fileManager.getJavaFileObjectsFromFiles( + Arrays.asList(srcDir.resolve("sample/SampleService.java").toFile()) + ); + + List options = Arrays.asList( + "-d", classesDir.toString(), + "-classpath", System.getProperty("java.class.path") + ); + + Boolean result = compiler.getTask(null, fileManager, diagnostics, options, null, units).call(); + fileManager.close(); + + if (result == null || !result) { + StringBuilder sb = new StringBuilder("Compilation failed:\n"); + for (Diagnostic diagnostic : diagnostics.getDiagnostics()) { + sb.append(diagnostic.getKind()).append(": ") + .append(diagnostic.getMessage(null)).append("\n"); + } + throw new IllegalStateException(sb.toString()); + } + } + + private ClassNode readClassNode(Path classFile) throws IOException { + byte[] bytes = Files.readAllBytes(classFile); + ClassReader reader = new ClassReader(bytes); + ClassNode node = new ClassNode(); + reader.accept(node, ClassReader.SKIP_DEBUG | ClassReader.SKIP_FRAMES); + return node; + } + + private MethodNode findMethod(ClassNode classNode, String name, String desc) { + Optional method = classNode.methods.stream() + .filter(m -> m.name.equals(name) && m.desc.equals(desc)) + .findFirst(); + return method.orElse(null); + } +} From aab9e00ffc09cef709704683d4c95c786b2fe800 Mon Sep 17 00:00:00 2001 From: Sergey Grigorchuk Date: Thu, 22 Jan 2026 20:17:01 +0000 Subject: [PATCH 3/3] release: prepare 0.2.4 defaults, logs, and samples sync - add global DebugLog defaults (plugin + env/system) - update log prefix to [KLB] and docs - add locals logging tests (JSON/HUMAN) - sync Maven/Gradle samples and bump versions to 0.2.4 --- AGENTS.md | 91 +++ CHANGELOG.md | 19 +- README.md | 201 +++++- RELEASE_NOTES_0.2.3.md | 10 +- RELEASE_NOTES_0.2.4.md | 23 + kolobok-annotations/pom.xml | 2 +- .../{LogContext.java => DebugLog.java} | 4 +- .../kolobok/annotation/DebugLogIgnore.java | 17 + .../org/kolobok/annotation/DebugLogMask.java | 13 + .../org/kolobok/runtime/LogContextTrace.java | 98 ++- kolobok-gradle-plugin/pom.xml | 2 +- .../org/kolobok/gradle/KolobokExtension.java | 170 +++++ .../kolobok/gradle/KolobokGradlePlugin.java | 1 + .../kolobok/gradle/KolobokTransformTask.java | 13 +- kolobok-maven-plugin/pom.xml | 2 +- .../org/kolobok/maven/KolobokMavenMojo.java | 69 +- kolobok-transformer/pom.xml | 3 +- .../kolobok/transformer/DebugLogDefaults.java | 243 +++++++ .../transformer/KolobokTransformer.java | 595 ++++++++++++++++-- .../LogContextHeatMapIntegrationTest.java | 4 +- .../LogContextIntegrationTest.java | 4 +- .../transformer/LogContextLineNumberTest.java | 4 +- .../LogContextLocalsHumanIntegrationTest.java | 119 ++++ .../LogContextLocalsIntegrationTest.java | 123 ++++ pom.xml | 2 +- samples/spring-data-jpa-gradle/build.gradle | 8 +- .../main/java/com/example/kolobok/Person.java | 48 +- .../com/example/kolobok/PersonController.java | 7 + .../com/example/kolobok/PersonService.java | 27 +- .../src/main/resources/application.properties | 2 + samples/spring-data-jpa-maven/pom.xml | 5 +- .../com/example/kolobok/PersonController.java | 4 +- .../com/example/kolobok/PersonService.java | 26 +- .../src/main/resources/application.properties | 2 + 34 files changed, 1839 insertions(+), 122 deletions(-) create mode 100644 AGENTS.md create mode 100644 RELEASE_NOTES_0.2.4.md rename kolobok-annotations/src/main/java/org/kolobok/annotation/{LogContext.java => DebugLog.java} (88%) create mode 100644 kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogIgnore.java create mode 100644 kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogMask.java create mode 100644 kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokExtension.java create mode 100644 kolobok-transformer/src/main/java/org/kolobok/transformer/DebugLogDefaults.java create mode 100644 kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsHumanIntegrationTest.java create mode 100644 kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsIntegrationTest.java diff --git a/AGENTS.md b/AGENTS.md new file mode 100644 index 0000000..8a08439 --- /dev/null +++ b/AGENTS.md @@ -0,0 +1,91 @@ +# AGENTS.md + +Этот файл — краткий конспект состояния проекта, решений и договоренностей. Нужен, чтобы быстро продолжать работу в будущих сессиях. + +## Контекст проекта +- Проект kolobok: инструмент для Spring Data репозиториев. +- Основная аннотация: `@FindWithOptionalParams` (генерация default-методов и абстрактных комбинаций). +- Цели: поддержка Java 21, Spring Boot 2.x (с прицелом на Spring 3 в будущем), сохранение привычного API. +- Переезд на Java 11+ проверен (11/17/21/25). + +## Текущая архитектура +- Модули: `kolobok-annotations`, `kolobok-transformer`, `kolobok-maven-plugin`, `kolobok-gradle-plugin`. +- Трансформер работает на байткоде (ASM), без javac internals. +- Версия ASM обновлена до 9.8 (нужно для Java 25). +- Релизная версия сейчас 0.2.4. + +## Новая аннотация @DebugLog +Реализована через байткод-трансформацию (не Spring AOP). + +Функции: +- лог входа/выхода/исключений и времени выполнения; +- использует существующий SLF4J логгер в классе (static field `log`, `logger`, `LOG`, `LOGGER`); +- при отсутствии логгера сборка должна падать; +- добавлены параметры: + - `lineHeatMap` + - `lineHeatMapOnException` + - `subHeatMap` + - `logDuration` + - `aggregateChildren` + - `logArgs` + - `mask` + - `maxArgLength` + - `logLevel` + - `logFormat` + - `logThreadId` + - `logThreadName` + +Внимание: +- если в классе нет SLF4J логгера — сборка падает. +- для heat map логов **нужен runtime** доступ к `kolobok` jar. + +### Параметры аргументов +- `logArgs` управляет выводом аргументов в entry-логах и JSON. +- `mask` маскирует аргументы по индексам (`"0,2-3"` или `"*"`). +- `maxArgLength` ограничивает длину строковых аргументов. +- `logLevel` задает уровень логов для entry/exit/heat map (по умолчанию `DEBUG`). +- `logFormat` переключает формат логов (`HUMAN` или `JSON`, по умолчанию `HUMAN`). +- `logThreadId`/`logThreadName` добавляют идентификатор/имя потока в логи. +- Аннотации `@DebugLogIgnore` и `@DebugLogMask` управляют скрытием/маскированием параметров и локальных переменных (локальные требуют debug symbols; сейчас захватываются только `int` и reference типы). +- Параметры `logLocals` и `logLocalsOnException` включают логирование всех локальных переменных (best-effort), кроме явно скрытых/маскированных. +- Глобальные дефолты DebugLog настраиваются без изменений в коде: приоритет аннотация > конфиг плагина > ENV/JVM > встроенные значения; ключи `kolobok.debuglog.*` и `KLB_DEBUGLOG_*`. + +## Heat map (lineHeatMap) +Логируется JSON-объект с тепловой картой строк. +Формат (единый, дерево): +```json +{ + "traceId": "...", + "method": "com.example.Foo#bar(Ljava/lang/String;I)Ljava/lang/String;", + "lineHeatMap": { "100-103": 1, "104": 10 }, + "durationNs": 123, + "children": [] +} +``` +Поддерживается вложенность: дочерние методы попадают в `children`. +traceId берется из MDC `traceId` (если есть), иначе UUID. +HUMAN-лог heatmap выводится многострочно с отступами и включает дочерние узлы. + +## Важные детали +- `@DebugLog` требует, чтобы `kolobok` был в runtime classpath. В samples убран `provided`/`compileOnly`. +- `PersonRepository` в samples теперь наследуется от `JpaRepository` (а не `CrudRepository`), т.к. default-метод вызывает `findAll()` с `List` типом. +- Для Maven sample включен DEBUG только для `com.example.kolobok`. +- Трансформер можно отключить без изменения кода: Maven `-Dkolobok.skip=true`, Gradle `-Pkolobok.skip=true`. + +## Скрипты запуска +- `run-java11.sh`, `run-java21.sh` в samples — запускают Maven/Gradle в offline режиме (`mvn -o`). +- Эти файлы исключены из git через `.gitignore`. + +## Известные предупреждения +- `~/.m2/settings.xml` содержит `` без корневого `` → warning. +- SLF4J warning про NOP provider в тестах (нормально для unit-тестов). + +## Что уже сделано +- Добавлен `@DebugLog`, тепловая карта, nested JSON, traceId. +- Добавлены тесты для DebugLog и line-number проверки. +- Обновлены README, CHANGELOG, RELEASE_NOTES_0.2.4. +- Проверка на Java 11/17/21/25. + +## Идеи/направления +- Уточнить/улучшить обработку `Iterable` vs `List` в `@FindWithOptionalParams`. +- Возможная опция: heat map в файл или JSON-отчет (сейчас — только лог). diff --git a/CHANGELOG.md b/CHANGELOG.md index 0589946..63b4d8a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,9 +2,26 @@ All notable changes to this project will be documented in this file. +## 0.2.4 +- Global DebugLog defaults via plugin config and ENV/JVM properties (annotation > plugin > env/sys > built-in). +- Added Gradle `kolobok { debugLogDefaults { ... } }` configuration. +- Added Maven `` configuration. +- New unit tests for locals logging (JSON/HUMAN). +- Switched log prefix to `[KLB]`. +- Synced Maven/Gradle samples (DebugLog usage, Lombok, logging config). +- Transformer now compiles against annotations module (compile-scope dependency). + ## 0.2.3 - Verified support for Java 11+ (tested on 11, 17, 21, 25) and updated build targets accordingly. -- Added `@LogContext` annotation with bytecode instrumentation for method entry/exit/exception logging using existing SLF4J logger fields. +- Added `@DebugLog` annotation with bytecode instrumentation for method entry/exit/exception logging using existing SLF4J logger fields. +- Added line heat map aggregation for `@DebugLog` with nested output, traceId, and optional duration logging. +- Added `logArgs`, `mask`, `maxArgLength`, `logLevel`, `logFormat`, `logThreadId`, and `logThreadName` options for `@DebugLog`. +- Expanded HUMAN heat map logs to include full nested details with indentation. +- Added Gradle support for `-Pkolobok.skip=true` to disable transformer. +- Added `@DebugLogIgnore` and `@DebugLogMask` for per-parameter and local-variable masking in error logs. +- Local-variable capture currently supports `int` and reference types. +- Added `logLocals` and `logLocalsOnException` options for `@DebugLog`. +- `logLocals`/`logLocalsOnException` now log all locals by default, unless ignored/masked. - Updated sample and example dependencies to 0.2.3. ## 0.2.0 diff --git a/README.md b/README.md index a7432d3..3f46d9e 100644 --- a/README.md +++ b/README.md @@ -71,8 +71,8 @@ Also it generates default implementation of `findByFirstNameAndLastNameAndCityId } ``` -## @LogContext -`@LogContext` logs method entry (arguments), return values, exceptions, and execution time using an existing logger field on the class. The transformer looks for a static logger field named `log`, `logger`, `LOG`, or `LOGGER` with type `org.slf4j.Logger`. Entry/exit/heat map logs are emitted at `logLevel` (default: `DEBUG`), exceptions at `error`. +## @DebugLog +`@DebugLog` logs method entry (arguments), return values, exceptions, and execution time using an existing logger field on the class. The transformer looks for a static logger field named `log`, `logger`, `LOG`, or `LOGGER` with type `org.slf4j.Logger`. Entry/exit/heat map logs are emitted at `logLevel` (default: `DEBUG`), exceptions at `error`. Optional flags: - `lineHeatMap` collects per-line hit counts and logs a compressed JSON heat map after method exit. @@ -89,14 +89,14 @@ Optional flags: - `logThreadName` adds `threadName` (default: false). ```java -import org.kolobok.annotation.LogContext; +import org.kolobok.annotation.DebugLog; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class SampleService { private static final Logger log = LoggerFactory.getLogger(SampleService.class); - @LogContext(lineHeatMap = true, logDuration = true) + @DebugLog(lineHeatMap = true, logDuration = true) public String work(String name, int count) { return name + count; } @@ -120,23 +120,198 @@ Heat map output format: Human log examples: ``` -[LC] ENTER com.example.Foo#bar(String, int):String trace=... t=32 tn=http-nio-8080-exec-1 args=["val1", 2] -[LC] EXIT com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns result=ok -[LC] ERROR com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns err=IllegalStateException:boom -[LC] HEATMAP com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns args=["val1", 2] heatmap={100-103:1,104:10} +[KLB] ENTER com.example.Foo#bar(String, int):String trace=... t=32 tn=http-nio-8080-exec-1 args=["val1", 2] +[KLB] EXIT com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns result=ok +[KLB] ERROR com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns err=IllegalStateException:boom +[KLB] HEATMAP com.example.Foo#bar(String, int):String trace=... t=32 dur=123456ns args=["val1", 2] heatmap={100-103:1,104:10} - com.example.Foo#child(String):void count=2 dur=4000ns args=["x"] heatmap={120:2} ``` ``` +## Global DebugLog Defaults +You can override defaults without touching source code. Precedence: +1) annotation values +2) Maven/Gradle plugin configuration +3) system properties / environment variables +4) built-in defaults + +Note: if an annotation value equals its built-in default, it is treated as "unset" and can be overridden. + +System properties (examples): +``` +-Dkolobok.debuglog.logLocals=true +-Dkolobok.debuglog.logFormat=JSON +-Dkolobok.debuglog.maxArgLength=500 +``` + +Environment variables (examples): +``` +KLB_DEBUGLOG_LOG_LOCALS=true +KLB_DEBUGLOG_LOG_FORMAT=JSON +KLB_DEBUGLOG_MAX_ARG_LENGTH=500 +``` + +Supported keys (system/env): +`lineHeatMap`, `lineHeatMapOnException`, `subHeatMap`, `logDuration`, `aggregateChildren`, `logArgs`, +`mask`, `maxArgLength`, `logLevel`, `logFormat`, `logThreadId`, `logThreadName`, `logLocals`, `logLocalsOnException`. + +Maven: +```xml + + + + com.github.ukman + kolobok-maven-plugin + 0.2.4 + + + true + JSON + 500 + + + + + +``` + +Gradle: +```gradle +kolobok { + debugLogDefaults { + logLocals = true + logFormat = "JSON" + maxArgLength = 500 + } +} +``` + +## Performance Overhead +`@DebugLog` is designed for debugging, not for always-on production use. Overhead depends on the depth of instrumentation, argument sizes, logging configuration, and whether heat maps are enabled. + +Max impact (worst cases): +- `lineHeatMap=true` on methods with tight loops or large code blocks (adds per-line counters). +- Deep call trees with many annotated methods. +- Large or expensive-to-stringify arguments or return values. +- Synchronous log appenders under load. + +Low impact scenarios: +- `lineHeatMap=false` and `logArgs=false` (minimal overhead). +- Only top-level endpoints are annotated. +- Logging level disabled by configuration (e.g., DEBUG off). + +Parameter impact: +- `lineHeatMap`: highest overhead; adds per-line increments. +- `lineHeatMapOnException`: same overhead as `lineHeatMap`, but logs only on errors. +- `subHeatMap`: reduces top-level log volume; no significant runtime savings. +- `logDuration`: minimal overhead (nanoTime). +- `aggregateChildren`: reduces log size; little runtime cost. +- `logArgs`: can be expensive if arguments are large or have heavy `toString`. +- `mask`: small overhead; applied during argument formatting. +- `maxArgLength`: reduces string size and memory usage; slight processing cost. +- `logFormat`: JSON is usually heavier than HUMAN (escaping/formatting). +- `logThreadId`/`logThreadName`: minimal overhead. +- `logLevel`: if logging level is disabled, most work is skipped early. +- `logLocals`: logs all local variables (best-effort, for `int` and reference types), except those marked with `@DebugLogIgnore` or `@DebugLogMask`. +- `logLocalsOnException`: logs locals only on exceptions (same rules as `logLocals`). + +## Parameter And Local Masking +You can control per-parameter and local-variable logging with annotations: + +```java +import org.kolobok.annotation.DebugLog; +import org.kolobok.annotation.DebugLogIgnore; +import org.kolobok.annotation.DebugLogMask; + +@DebugLog +void doPost(@DebugLogIgnore String cardNumber, + @DebugLogMask(first = 2, last = 4) String passport) { + @DebugLogIgnore(mode = DebugLogIgnore.Mode.SUCCESS) + String tmp = loadTemp(); + @DebugLogMask(first = 2, last = 4) + String secret = readSecret(); + // ... +} +``` + +Notes: +- `@DebugLogIgnore` hides the value completely. +- `@DebugLogIgnore(mode = SUCCESS)` hides the value on success, but shows it on exceptions. +- `@DebugLogMask(first,last)` prints only the first/last characters, masking the middle. +- Local-variable annotations require debug symbols (`-g`) and are best-effort (based on local variable tables). +- Local-variable capture currently tracks `int` and reference types; other primitives are ignored. + +## Disable Transformer For Production Builds +You can disable bytecode transformation without changing source code. + +Maven: +``` +mvn -Dkolobok.skip=true package +``` +Or in `pom.xml`: +```xml + + + + com.github.ukman + kolobok-maven-plugin + 0.2.4 + + true + + + + +``` +Or using a `prod` profile: +```xml + + + prod + + + + com.github.ukman + kolobok-maven-plugin + 0.2.4 + + true + + + + + + +``` + +Gradle: +``` +./gradlew build -Pkolobok.skip=true +``` +Or in `build.gradle`: +```groovy +tasks.named("kolobokTransform").configure { + enabled = false +} +``` +Or with a `prod` property: +```groovy +if (project.hasProperty("prod")) { + tasks.named("kolobokTransform").configure { + enabled = false + } +} +``` + ## How to use Kolobok? -Kolobok uses a bytecode transformer after compilation, so no special compiler flags are needed. It works on Java 11 and newer (verified on 11, 17, 21, 25). If you enable `@LogContext` heat maps, ensure the `kolobok` jar is available at runtime (do not use `provided`/`compileOnly`). +Kolobok uses a bytecode transformer after compilation, so no special compiler flags are needed. It works on Java 11 and newer (verified on 11, 17, 21, 25). If you enable `@DebugLog` heat maps, ensure the `kolobok` jar is available at runtime (do not use `provided`/`compileOnly`). Maven: ```xml com.github.ukman kolobok - 0.2.3 + 0.2.4 provided @@ -145,7 +320,7 @@ Maven: com.github.ukman kolobok-maven-plugin - 0.2.3 + 0.2.4 @@ -161,12 +336,12 @@ Maven: Gradle: ```gradle dependencies { - compileOnly 'com.github.ukman:kolobok:0.2.3' + compileOnly 'com.github.ukman:kolobok:0.2.4' } buildscript { dependencies { - classpath 'com.github.ukman:kolobok-gradle-plugin:0.2.3' + classpath 'com.github.ukman:kolobok-gradle-plugin:0.2.4' } } diff --git a/RELEASE_NOTES_0.2.3.md b/RELEASE_NOTES_0.2.3.md index 8557b3d..7b03361 100644 --- a/RELEASE_NOTES_0.2.3.md +++ b/RELEASE_NOTES_0.2.3.md @@ -2,7 +2,15 @@ ## Highlights - Verified Java 11+ compatibility (tested on 11, 17, 21, 25) and adjusted build targets. -- Added `@LogContext` instrumentation that logs method entry/exit/exception timing using existing SLF4J logger fields. +- Added `@DebugLog` instrumentation that logs method entry/exit/exception timing using existing SLF4J logger fields. +- Added `@DebugLog` line heat map output with nested JSON, traceId, and optional duration logging. +- Added `@DebugLog` options for `logArgs`, `mask`, `maxArgLength`, `logLevel`, `logFormat`, `logThreadId`, and `logThreadName`. +- Expanded HUMAN heat map logs to include full nested details with indentation. +- Added Gradle support for `-Pkolobok.skip=true` to disable transformer. +- Added `@DebugLogIgnore` and `@DebugLogMask` for per-parameter and local-variable masking in error logs. +- Local-variable capture currently supports `int` and reference types. +- Added `logLocals` and `logLocalsOnException` options for `@DebugLog`. +- `logLocals`/`logLocalsOnException` now log all locals by default, unless ignored/masked. - Updated samples and example dependencies to 0.2.3. ## Compatibility diff --git a/RELEASE_NOTES_0.2.4.md b/RELEASE_NOTES_0.2.4.md new file mode 100644 index 0000000..f24355d --- /dev/null +++ b/RELEASE_NOTES_0.2.4.md @@ -0,0 +1,23 @@ +# Kolobok 0.2.4 Release Notes + +## Highlights +- Global DebugLog defaults via plugin config and ENV/JVM properties. +- New unit tests for local-variable logging (JSON and HUMAN formats). +- Log prefix switched to `[KLB]` for easier filtering. +- Maven and Gradle samples synchronized. + +## Changes +- DebugLog defaults precedence: annotation > plugin config > env/system > built-in defaults. +- Gradle plugin adds `kolobok { debugLogDefaults { ... } }` configuration. +- Maven plugin adds `` configuration block. +- Transformer now depends on annotations module at compile time. +- Added locals logging integration tests. +- Updated sample apps to use DebugLog consistently, Lombok in Gradle sample, and matching logging config. + +## Migration Notes +- `@LogContext` was removed in favor of `@DebugLog` (breaking change if still referenced). +- Log prefix changed from `[LC]` to `[KLB]`. + +## Compatibility +- Java 11+ (verified 11/17/21/25). +- Spring Boot 2.x compatible; Spring 3 target remains supported. diff --git a/kolobok-annotations/pom.xml b/kolobok-annotations/pom.xml index 07ea37d..b8bb84f 100644 --- a/kolobok-annotations/pom.xml +++ b/kolobok-annotations/pom.xml @@ -7,7 +7,7 @@ com.github.ukman kolobok-parent - 0.2.3 + 0.2.4 kolobok diff --git a/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLog.java similarity index 88% rename from kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java rename to kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLog.java index 8367763..b592211 100644 --- a/kolobok-annotations/src/main/java/org/kolobok/annotation/LogContext.java +++ b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLog.java @@ -7,7 +7,7 @@ @Retention(RetentionPolicy.CLASS) @Target({ElementType.TYPE, ElementType.METHOD}) -public @interface LogContext { +public @interface DebugLog { boolean lineHeatMap() default false; boolean lineHeatMapOnException() default false; boolean subHeatMap() default false; @@ -20,6 +20,8 @@ LogFormat logFormat() default LogFormat.HUMAN; boolean logThreadId() default false; boolean logThreadName() default false; + boolean logLocals() default false; + boolean logLocalsOnException() default false; enum LogLevel { TRACE, diff --git a/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogIgnore.java b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogIgnore.java new file mode 100644 index 0000000..976dad2 --- /dev/null +++ b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogIgnore.java @@ -0,0 +1,17 @@ +package org.kolobok.annotation; + +import java.lang.annotation.ElementType; +import java.lang.annotation.Retention; +import java.lang.annotation.RetentionPolicy; +import java.lang.annotation.Target; + +@Retention(RetentionPolicy.CLASS) +@Target({ElementType.PARAMETER, ElementType.LOCAL_VARIABLE}) +public @interface DebugLogIgnore { + Mode mode() default Mode.ALWAYS; + + enum Mode { + ALWAYS, + SUCCESS + } +} diff --git a/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogMask.java b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogMask.java new file mode 100644 index 0000000..2ee9001 --- /dev/null +++ b/kolobok-annotations/src/main/java/org/kolobok/annotation/DebugLogMask.java @@ -0,0 +1,13 @@ +package org.kolobok.annotation; + +import java.lang.annotation.ElementType; +import java.lang.annotation.Retention; +import java.lang.annotation.RetentionPolicy; +import java.lang.annotation.Target; + +@Retention(RetentionPolicy.CLASS) +@Target({ElementType.PARAMETER, ElementType.LOCAL_VARIABLE}) +public @interface DebugLogMask { + int first() default 0; + int last() default 0; +} diff --git a/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java b/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java index 11544bf..308e75e 100644 --- a/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java +++ b/kolobok-annotations/src/main/java/org/kolobok/runtime/LogContextTrace.java @@ -191,6 +191,102 @@ public static String formatArgsJson(Object[] args, String mask, int maxArgLength return sb.toString(); } + public static String maskValue(Object value, int first, int last, int maxArgLength) { + if (value == null) { + return "null"; + } + String raw = String.valueOf(value); + String truncated = truncate(raw, maxArgLength > 0 ? maxArgLength : 200); + if (first <= 0 && last <= 0) { + return "***"; + } + int length = truncated.length(); + int prefix = Math.max(0, first); + int suffix = Math.max(0, last); + if (prefix + suffix >= length) { + return truncated; + } + String start = truncated.substring(0, prefix); + String end = truncated.substring(length - suffix); + return start + "***" + end; + } + + public static String formatLocalsHuman(Object[] locals, String[] names, int[] ignoreModes, + int[] maskFirst, int[] maskLast, boolean isException, int maxArgLength) { + StringBuilder sb = new StringBuilder(); + boolean first = true; + if (names == null || locals == null) { + return ""; + } + for (int i = 0; i < names.length; i++) { + String name = names[i]; + if (name == null) { + continue; + } + int mode = ignoreModes != null && i < ignoreModes.length ? ignoreModes[i] : 0; + if (mode == 1) { + continue; + } + if (mode == 2 && !isException) { + continue; + } + Object value = i < locals.length ? locals[i] : null; + String out; + int firstCount = maskFirst != null && i < maskFirst.length ? maskFirst[i] : 0; + int lastCount = maskLast != null && i < maskLast.length ? maskLast[i] : 0; + if (firstCount > 0 || lastCount > 0) { + out = maskValue(value, firstCount, lastCount, maxArgLength); + } else { + out = truncate(String.valueOf(value), maxArgLength > 0 ? maxArgLength : 200); + } + if (!first) { + sb.append(", "); + } + first = false; + sb.append(name).append('=').append(out); + } + return sb.toString(); + } + + public static String formatLocalsJson(Object[] locals, String[] names, int[] ignoreModes, + int[] maskFirst, int[] maskLast, boolean isException, int maxArgLength) { + StringBuilder sb = new StringBuilder(); + boolean first = true; + if (names == null || locals == null) { + return "{}"; + } + sb.append('{'); + for (int i = 0; i < names.length; i++) { + String name = names[i]; + if (name == null) { + continue; + } + int mode = ignoreModes != null && i < ignoreModes.length ? ignoreModes[i] : 0; + if (mode == 1) { + continue; + } + if (mode == 2 && !isException) { + continue; + } + Object value = i < locals.length ? locals[i] : null; + String out; + int firstCount = maskFirst != null && i < maskFirst.length ? maskFirst[i] : 0; + int lastCount = maskLast != null && i < maskLast.length ? maskLast[i] : 0; + if (firstCount > 0 || lastCount > 0) { + out = maskValue(value, firstCount, lastCount, maxArgLength); + } else { + out = truncate(String.valueOf(value), maxArgLength > 0 ? maxArgLength : 200); + } + if (!first) { + sb.append(','); + } + first = false; + sb.append('"').append(escapeJson(name)).append("\":\"").append(escapeJson(out)).append('"'); + } + sb.append('}'); + return sb.toString(); + } + private static final class TraceState { private final String traceId; private final boolean suppressedRoot; @@ -271,7 +367,7 @@ private static String buildHumanHeatMap(String traceId, TraceNode node, boolean private static void appendHumanNode(StringBuilder sb, TraceNode node, int depth, String traceId, boolean logThreadId, boolean logThreadName) { if (depth == 0) { - sb.append("[LC] HEATMAP "); + sb.append("[KLB] HEATMAP "); } else { for (int i = 0; i < depth; i++) { sb.append(" "); diff --git a/kolobok-gradle-plugin/pom.xml b/kolobok-gradle-plugin/pom.xml index 5d8e7c3..cb714e0 100644 --- a/kolobok-gradle-plugin/pom.xml +++ b/kolobok-gradle-plugin/pom.xml @@ -7,7 +7,7 @@ com.github.ukman kolobok-parent - 0.2.3 + 0.2.4 kolobok-gradle-plugin diff --git a/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokExtension.java b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokExtension.java new file mode 100644 index 0000000..58a03b9 --- /dev/null +++ b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokExtension.java @@ -0,0 +1,170 @@ +package org.kolobok.gradle; + +import org.kolobok.annotation.DebugLog; +import org.kolobok.transformer.DebugLogDefaults; + +import java.util.Locale; + +public class KolobokExtension { + private final DebugLogDefaultsConfig debugLogDefaults = new DebugLogDefaultsConfig(); + + public DebugLogDefaultsConfig getDebugLogDefaults() { + return debugLogDefaults; + } + + public static class DebugLogDefaultsConfig { + private Boolean lineHeatMap; + private Boolean lineHeatMapOnException; + private Boolean subHeatMap; + private Boolean logDuration; + private Boolean aggregateChildren; + private Boolean logArgs; + private String mask; + private Integer maxArgLength; + private String logLevel; + private String logFormat; + private Boolean logThreadId; + private Boolean logThreadName; + private Boolean logLocals; + private Boolean logLocalsOnException; + + public DebugLogDefaults toDefaults() { + DebugLogDefaults defaults = new DebugLogDefaults(); + defaults.setLineHeatMap(lineHeatMap); + defaults.setLineHeatMapOnException(lineHeatMapOnException); + defaults.setSubHeatMap(subHeatMap); + defaults.setLogDuration(logDuration); + defaults.setAggregateChildren(aggregateChildren); + defaults.setLogArgs(logArgs); + defaults.setMask(mask); + defaults.setMaxArgLength(maxArgLength); + if (logLevel != null) { + defaults.setLogLevel(parseEnum(DebugLog.LogLevel.class, logLevel)); + } + if (logFormat != null) { + defaults.setLogFormat(parseEnum(DebugLog.LogFormat.class, logFormat)); + } + defaults.setLogThreadId(logThreadId); + defaults.setLogThreadName(logThreadName); + defaults.setLogLocals(logLocals); + defaults.setLogLocalsOnException(logLocalsOnException); + return defaults; + } + + private > T parseEnum(Class type, String value) { + return Enum.valueOf(type, value.trim().toUpperCase(Locale.ROOT)); + } + + public Boolean getLineHeatMap() { + return lineHeatMap; + } + + public void setLineHeatMap(Boolean lineHeatMap) { + this.lineHeatMap = lineHeatMap; + } + + public Boolean getLineHeatMapOnException() { + return lineHeatMapOnException; + } + + public void setLineHeatMapOnException(Boolean lineHeatMapOnException) { + this.lineHeatMapOnException = lineHeatMapOnException; + } + + public Boolean getSubHeatMap() { + return subHeatMap; + } + + public void setSubHeatMap(Boolean subHeatMap) { + this.subHeatMap = subHeatMap; + } + + public Boolean getLogDuration() { + return logDuration; + } + + public void setLogDuration(Boolean logDuration) { + this.logDuration = logDuration; + } + + public Boolean getAggregateChildren() { + return aggregateChildren; + } + + public void setAggregateChildren(Boolean aggregateChildren) { + this.aggregateChildren = aggregateChildren; + } + + public Boolean getLogArgs() { + return logArgs; + } + + public void setLogArgs(Boolean logArgs) { + this.logArgs = logArgs; + } + + public String getMask() { + return mask; + } + + public void setMask(String mask) { + this.mask = mask; + } + + public Integer getMaxArgLength() { + return maxArgLength; + } + + public void setMaxArgLength(Integer maxArgLength) { + this.maxArgLength = maxArgLength; + } + + public String getLogLevel() { + return logLevel; + } + + public void setLogLevel(String logLevel) { + this.logLevel = logLevel; + } + + public String getLogFormat() { + return logFormat; + } + + public void setLogFormat(String logFormat) { + this.logFormat = logFormat; + } + + public Boolean getLogThreadId() { + return logThreadId; + } + + public void setLogThreadId(Boolean logThreadId) { + this.logThreadId = logThreadId; + } + + public Boolean getLogThreadName() { + return logThreadName; + } + + public void setLogThreadName(Boolean logThreadName) { + this.logThreadName = logThreadName; + } + + public Boolean getLogLocals() { + return logLocals; + } + + public void setLogLocals(Boolean logLocals) { + this.logLocals = logLocals; + } + + public Boolean getLogLocalsOnException() { + return logLocalsOnException; + } + + public void setLogLocalsOnException(Boolean logLocalsOnException) { + this.logLocalsOnException = logLocalsOnException; + } + } +} diff --git a/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokGradlePlugin.java b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokGradlePlugin.java index f792db4..182196c 100644 --- a/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokGradlePlugin.java +++ b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokGradlePlugin.java @@ -11,6 +11,7 @@ public class KolobokGradlePlugin implements Plugin { @Override public void apply(Project project) { + project.getExtensions().create("kolobok", KolobokExtension.class); project.getPlugins().withType(JavaPlugin.class, plugin -> { SourceSetContainer sourceSets = project.getExtensions().getByType(SourceSetContainer.class); SourceSet main = sourceSets.getByName(SourceSet.MAIN_SOURCE_SET_NAME); diff --git a/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokTransformTask.java b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokTransformTask.java index b08d240..ab7a468 100644 --- a/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokTransformTask.java +++ b/kolobok-gradle-plugin/src/main/java/org/kolobok/gradle/KolobokTransformTask.java @@ -4,6 +4,7 @@ import org.gradle.api.file.ConfigurableFileCollection; import org.gradle.api.tasks.InputFiles; import org.gradle.api.tasks.TaskAction; +import org.kolobok.transformer.DebugLogDefaults; import org.kolobok.transformer.KolobokTransformer; import java.io.File; @@ -20,7 +21,17 @@ public ConfigurableFileCollection getClassesDirs() { @TaskAction public void transform() throws IOException { - KolobokTransformer transformer = new KolobokTransformer(); + Object skipProp = getProject().findProperty("kolobok.skip"); + if (skipProp != null && Boolean.parseBoolean(skipProp.toString())) { + getLogger().lifecycle("Kolobok transform skipped"); + return; + } + DebugLogDefaults defaults = DebugLogDefaults.fromSystemEnv(); + KolobokExtension extension = getProject().getExtensions().findByType(KolobokExtension.class); + if (extension != null) { + defaults = defaults.merge(extension.getDebugLogDefaults().toDefaults()); + } + KolobokTransformer transformer = new KolobokTransformer(defaults); for (File dir : classesDirs) { transformer.transformDirectory(dir.toPath()); } diff --git a/kolobok-maven-plugin/pom.xml b/kolobok-maven-plugin/pom.xml index 9132c3e..2f688b5 100644 --- a/kolobok-maven-plugin/pom.xml +++ b/kolobok-maven-plugin/pom.xml @@ -7,7 +7,7 @@ com.github.ukman kolobok-parent - 0.2.3 + 0.2.4 kolobok-maven-plugin diff --git a/kolobok-maven-plugin/src/main/java/org/kolobok/maven/KolobokMavenMojo.java b/kolobok-maven-plugin/src/main/java/org/kolobok/maven/KolobokMavenMojo.java index 851b9ed..3794165 100644 --- a/kolobok-maven-plugin/src/main/java/org/kolobok/maven/KolobokMavenMojo.java +++ b/kolobok-maven-plugin/src/main/java/org/kolobok/maven/KolobokMavenMojo.java @@ -5,6 +5,8 @@ import org.apache.maven.plugins.annotations.LifecyclePhase; import org.apache.maven.plugins.annotations.Mojo; import org.apache.maven.plugins.annotations.Parameter; +import org.kolobok.annotation.DebugLog; +import org.kolobok.transformer.DebugLogDefaults; import org.kolobok.transformer.KolobokTransformer; import java.io.IOException; @@ -19,6 +21,9 @@ public class KolobokMavenMojo extends AbstractMojo { @Parameter(property = "kolobok.skip", defaultValue = "false") private boolean skip; + @Parameter + private DebugLogDefaultsConfig debugLogDefaults; + @Override public void execute() throws MojoExecutionException { if (skip) { @@ -30,10 +35,72 @@ public void execute() throws MojoExecutionException { return; } try { - KolobokTransformer transformer = new KolobokTransformer(); + DebugLogDefaults defaults = DebugLogDefaults.fromSystemEnv(); + if (debugLogDefaults != null) { + defaults = defaults.merge(debugLogDefaults.toDefaults()); + } + KolobokTransformer transformer = new KolobokTransformer(defaults); transformer.transformDirectory(Path.of(classesDirectory)); } catch (IOException e) { throw new MojoExecutionException("Failed to transform classes in " + classesDirectory, e); } } + + public static class DebugLogDefaultsConfig { + @Parameter + private Boolean lineHeatMap; + @Parameter + private Boolean lineHeatMapOnException; + @Parameter + private Boolean subHeatMap; + @Parameter + private Boolean logDuration; + @Parameter + private Boolean aggregateChildren; + @Parameter + private Boolean logArgs; + @Parameter + private String mask; + @Parameter + private Integer maxArgLength; + @Parameter + private String logLevel; + @Parameter + private String logFormat; + @Parameter + private Boolean logThreadId; + @Parameter + private Boolean logThreadName; + @Parameter + private Boolean logLocals; + @Parameter + private Boolean logLocalsOnException; + + private DebugLogDefaults toDefaults() { + DebugLogDefaults defaults = new DebugLogDefaults(); + defaults.setLineHeatMap(lineHeatMap); + defaults.setLineHeatMapOnException(lineHeatMapOnException); + defaults.setSubHeatMap(subHeatMap); + defaults.setLogDuration(logDuration); + defaults.setAggregateChildren(aggregateChildren); + defaults.setLogArgs(logArgs); + defaults.setMask(mask); + defaults.setMaxArgLength(maxArgLength); + if (logLevel != null) { + defaults.setLogLevel(parseEnum(DebugLog.LogLevel.class, logLevel)); + } + if (logFormat != null) { + defaults.setLogFormat(parseEnum(DebugLog.LogFormat.class, logFormat)); + } + defaults.setLogThreadId(logThreadId); + defaults.setLogThreadName(logThreadName); + defaults.setLogLocals(logLocals); + defaults.setLogLocalsOnException(logLocalsOnException); + return defaults; + } + + private > T parseEnum(Class type, String value) { + return Enum.valueOf(type, value.trim().toUpperCase(java.util.Locale.ROOT)); + } + } } diff --git a/kolobok-transformer/pom.xml b/kolobok-transformer/pom.xml index 97beff4..63cb9be 100644 --- a/kolobok-transformer/pom.xml +++ b/kolobok-transformer/pom.xml @@ -7,7 +7,7 @@ com.github.ukman kolobok-parent - 0.2.3 + 0.2.4 kolobok-transformer @@ -19,7 +19,6 @@ com.github.ukman kolobok ${project.version} - test org.ow2.asm diff --git a/kolobok-transformer/src/main/java/org/kolobok/transformer/DebugLogDefaults.java b/kolobok-transformer/src/main/java/org/kolobok/transformer/DebugLogDefaults.java new file mode 100644 index 0000000..64723bc --- /dev/null +++ b/kolobok-transformer/src/main/java/org/kolobok/transformer/DebugLogDefaults.java @@ -0,0 +1,243 @@ +package org.kolobok.transformer; + +import org.kolobok.annotation.DebugLog; + +import java.util.Locale; + +public final class DebugLogDefaults { + public static final boolean DEFAULT_LINE_HEAT_MAP = false; + public static final boolean DEFAULT_LINE_HEAT_MAP_ON_EXCEPTION = false; + public static final boolean DEFAULT_SUB_HEAT_MAP = false; + public static final boolean DEFAULT_LOG_DURATION = false; + public static final boolean DEFAULT_AGGREGATE_CHILDREN = true; + public static final boolean DEFAULT_LOG_ARGS = true; + public static final String DEFAULT_MASK = ""; + public static final int DEFAULT_MAX_ARG_LENGTH = 200; + public static final DebugLog.LogLevel DEFAULT_LOG_LEVEL = DebugLog.LogLevel.DEBUG; + public static final DebugLog.LogFormat DEFAULT_LOG_FORMAT = DebugLog.LogFormat.HUMAN; + public static final boolean DEFAULT_LOG_THREAD_ID = false; + public static final boolean DEFAULT_LOG_THREAD_NAME = false; + public static final boolean DEFAULT_LOG_LOCALS = false; + public static final boolean DEFAULT_LOG_LOCALS_ON_EXCEPTION = false; + + private Boolean lineHeatMap; + private Boolean lineHeatMapOnException; + private Boolean subHeatMap; + private Boolean logDuration; + private Boolean aggregateChildren; + private Boolean logArgs; + private String mask; + private Integer maxArgLength; + private DebugLog.LogLevel logLevel; + private DebugLog.LogFormat logFormat; + private Boolean logThreadId; + private Boolean logThreadName; + private Boolean logLocals; + private Boolean logLocalsOnException; + + public static DebugLogDefaults fromSystemEnv() { + DebugLogDefaults defaults = new DebugLogDefaults(); + defaults.lineHeatMap = readBoolean("kolobok.debuglog.lineHeatMap", "KLB_DEBUGLOG_LINE_HEAT_MAP"); + defaults.lineHeatMapOnException = readBoolean("kolobok.debuglog.lineHeatMapOnException", + "KLB_DEBUGLOG_LINE_HEAT_MAP_ON_EXCEPTION"); + defaults.subHeatMap = readBoolean("kolobok.debuglog.subHeatMap", "KLB_DEBUGLOG_SUB_HEAT_MAP"); + defaults.logDuration = readBoolean("kolobok.debuglog.logDuration", "KLB_DEBUGLOG_LOG_DURATION"); + defaults.aggregateChildren = readBoolean("kolobok.debuglog.aggregateChildren", "KLB_DEBUGLOG_AGGREGATE_CHILDREN"); + defaults.logArgs = readBoolean("kolobok.debuglog.logArgs", "KLB_DEBUGLOG_LOG_ARGS"); + defaults.mask = readString("kolobok.debuglog.mask", "KLB_DEBUGLOG_MASK"); + defaults.maxArgLength = readInt("kolobok.debuglog.maxArgLength", "KLB_DEBUGLOG_MAX_ARG_LENGTH"); + defaults.logLevel = readEnum(DebugLog.LogLevel.class, "kolobok.debuglog.logLevel", "KLB_DEBUGLOG_LOG_LEVEL"); + defaults.logFormat = readEnum(DebugLog.LogFormat.class, "kolobok.debuglog.logFormat", "KLB_DEBUGLOG_LOG_FORMAT"); + defaults.logThreadId = readBoolean("kolobok.debuglog.logThreadId", "KLB_DEBUGLOG_LOG_THREAD_ID"); + defaults.logThreadName = readBoolean("kolobok.debuglog.logThreadName", "KLB_DEBUGLOG_LOG_THREAD_NAME"); + defaults.logLocals = readBoolean("kolobok.debuglog.logLocals", "KLB_DEBUGLOG_LOG_LOCALS"); + defaults.logLocalsOnException = readBoolean("kolobok.debuglog.logLocalsOnException", + "KLB_DEBUGLOG_LOG_LOCALS_ON_EXCEPTION"); + return defaults; + } + + public DebugLogDefaults merge(DebugLogDefaults overrides) { + if (overrides == null) { + return this; + } + DebugLogDefaults merged = new DebugLogDefaults(); + merged.lineHeatMap = overrides.lineHeatMap != null ? overrides.lineHeatMap : lineHeatMap; + merged.lineHeatMapOnException = overrides.lineHeatMapOnException != null ? overrides.lineHeatMapOnException : lineHeatMapOnException; + merged.subHeatMap = overrides.subHeatMap != null ? overrides.subHeatMap : subHeatMap; + merged.logDuration = overrides.logDuration != null ? overrides.logDuration : logDuration; + merged.aggregateChildren = overrides.aggregateChildren != null ? overrides.aggregateChildren : aggregateChildren; + merged.logArgs = overrides.logArgs != null ? overrides.logArgs : logArgs; + merged.mask = overrides.mask != null ? overrides.mask : mask; + merged.maxArgLength = overrides.maxArgLength != null ? overrides.maxArgLength : maxArgLength; + merged.logLevel = overrides.logLevel != null ? overrides.logLevel : logLevel; + merged.logFormat = overrides.logFormat != null ? overrides.logFormat : logFormat; + merged.logThreadId = overrides.logThreadId != null ? overrides.logThreadId : logThreadId; + merged.logThreadName = overrides.logThreadName != null ? overrides.logThreadName : logThreadName; + merged.logLocals = overrides.logLocals != null ? overrides.logLocals : logLocals; + merged.logLocalsOnException = overrides.logLocalsOnException != null ? overrides.logLocalsOnException : logLocalsOnException; + return merged; + } + + public Boolean getLineHeatMap() { + return lineHeatMap; + } + + public void setLineHeatMap(Boolean lineHeatMap) { + this.lineHeatMap = lineHeatMap; + } + + public Boolean getLineHeatMapOnException() { + return lineHeatMapOnException; + } + + public void setLineHeatMapOnException(Boolean lineHeatMapOnException) { + this.lineHeatMapOnException = lineHeatMapOnException; + } + + public Boolean getSubHeatMap() { + return subHeatMap; + } + + public void setSubHeatMap(Boolean subHeatMap) { + this.subHeatMap = subHeatMap; + } + + public Boolean getLogDuration() { + return logDuration; + } + + public void setLogDuration(Boolean logDuration) { + this.logDuration = logDuration; + } + + public Boolean getAggregateChildren() { + return aggregateChildren; + } + + public void setAggregateChildren(Boolean aggregateChildren) { + this.aggregateChildren = aggregateChildren; + } + + public Boolean getLogArgs() { + return logArgs; + } + + public void setLogArgs(Boolean logArgs) { + this.logArgs = logArgs; + } + + public String getMask() { + return mask; + } + + public void setMask(String mask) { + this.mask = mask; + } + + public Integer getMaxArgLength() { + return maxArgLength; + } + + public void setMaxArgLength(Integer maxArgLength) { + this.maxArgLength = maxArgLength; + } + + public DebugLog.LogLevel getLogLevel() { + return logLevel; + } + + public void setLogLevel(DebugLog.LogLevel logLevel) { + this.logLevel = logLevel; + } + + public DebugLog.LogFormat getLogFormat() { + return logFormat; + } + + public void setLogFormat(DebugLog.LogFormat logFormat) { + this.logFormat = logFormat; + } + + public Boolean getLogThreadId() { + return logThreadId; + } + + public void setLogThreadId(Boolean logThreadId) { + this.logThreadId = logThreadId; + } + + public Boolean getLogThreadName() { + return logThreadName; + } + + public void setLogThreadName(Boolean logThreadName) { + this.logThreadName = logThreadName; + } + + public Boolean getLogLocals() { + return logLocals; + } + + public void setLogLocals(Boolean logLocals) { + this.logLocals = logLocals; + } + + public Boolean getLogLocalsOnException() { + return logLocalsOnException; + } + + public void setLogLocalsOnException(Boolean logLocalsOnException) { + this.logLocalsOnException = logLocalsOnException; + } + + private static Boolean readBoolean(String propKey, String envKey) { + String value = readString(propKey, envKey); + if (value == null) { + return null; + } + String normalized = value.trim().toLowerCase(Locale.ROOT); + if ("true".equals(normalized) || "1".equals(normalized) || "yes".equals(normalized)) { + return Boolean.TRUE; + } + if ("false".equals(normalized) || "0".equals(normalized) || "no".equals(normalized)) { + return Boolean.FALSE; + } + return null; + } + + private static Integer readInt(String propKey, String envKey) { + String value = readString(propKey, envKey); + if (value == null || value.trim().isEmpty()) { + return null; + } + try { + return Integer.parseInt(value.trim()); + } catch (NumberFormatException ex) { + return null; + } + } + + private static String readString(String propKey, String envKey) { + String value = System.getProperty(propKey); + if (value != null && !value.trim().isEmpty()) { + return value.trim(); + } + value = System.getenv(envKey); + if (value != null && !value.trim().isEmpty()) { + return value.trim(); + } + return null; + } + + private static > T readEnum(Class type, String propKey, String envKey) { + String value = readString(propKey, envKey); + if (value == null) { + return null; + } + try { + return Enum.valueOf(type, value.trim().toUpperCase(Locale.ROOT)); + } catch (IllegalArgumentException ex) { + return null; + } + } +} diff --git a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java index 4c7f26a..04642a2 100644 --- a/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java +++ b/kolobok-transformer/src/main/java/org/kolobok/transformer/KolobokTransformer.java @@ -14,10 +14,13 @@ import org.objectweb.asm.tree.IntInsnNode; import org.objectweb.asm.tree.InsnList; import org.objectweb.asm.tree.InsnNode; +import org.objectweb.asm.tree.IincInsnNode; import org.objectweb.asm.tree.JumpInsnNode; import org.objectweb.asm.tree.LabelNode; import org.objectweb.asm.tree.LdcInsnNode; import org.objectweb.asm.tree.LineNumberNode; +import org.objectweb.asm.tree.LocalVariableAnnotationNode; +import org.objectweb.asm.tree.LocalVariableNode; import org.objectweb.asm.tree.MethodInsnNode; import org.objectweb.asm.tree.MethodNode; import org.objectweb.asm.tree.TryCatchBlockNode; @@ -39,9 +42,20 @@ public class KolobokTransformer { public static final String OPTIONAL_PARAMS_DESC = "Lorg/kolobok/annotation/FindWithOptionalParams;"; - public static final String LOG_CONTEXT_DESC = "Lorg/kolobok/annotation/LogContext;"; + public static final String DEBUG_LOG_DESC = "Lorg/kolobok/annotation/DebugLog;"; + public static final String DEBUG_LOG_IGNORE_DESC = "Lorg/kolobok/annotation/DebugLogIgnore;"; + public static final String DEBUG_LOG_MASK_DESC = "Lorg/kolobok/annotation/DebugLogMask;"; private static final String SLF4J_LOGGER_DESC = "Lorg/slf4j/Logger;"; private static final String[] LOGGER_FIELD_NAMES = {"log", "logger", "LOG", "LOGGER"}; + private final DebugLogDefaults defaults; + + public KolobokTransformer() { + this(DebugLogDefaults.fromSystemEnv()); + } + + public KolobokTransformer(DebugLogDefaults defaults) { + this.defaults = defaults == null ? new DebugLogDefaults() : defaults; + } private final RepoMethodUtil repoMethodUtil = new RepoMethodUtil(); @@ -119,9 +133,9 @@ private boolean transformInterface(ClassNode classNode) { } private boolean transformLogContext(ClassNode classNode) { - AnnotationNode classAnnotation = findAnnotation(classNode.visibleAnnotations, LOG_CONTEXT_DESC); + AnnotationNode classAnnotation = findAnnotation(classNode.visibleAnnotations, DEBUG_LOG_DESC); if (classAnnotation == null) { - classAnnotation = findAnnotation(classNode.invisibleAnnotations, LOG_CONTEXT_DESC); + classAnnotation = findAnnotation(classNode.invisibleAnnotations, DEBUG_LOG_DESC); } Map methodsToInstrument = new HashMap<>(); @@ -139,7 +153,7 @@ private boolean transformLogContext(ClassNode classNode) { FieldNode loggerField = findLoggerField(classNode); if (loggerField == null) { throw new IllegalStateException("Class '" + classNode.name - + "' uses @LogContext but no static logger field named log/logger/LOG/LOGGER with type org.slf4j.Logger was found"); + + "' uses @DebugLog but no static logger field named log/logger/LOG/LOGGER with type org.slf4j.Logger was found"); } for (Map.Entry entry : methodsToInstrument.entrySet()) { @@ -163,31 +177,79 @@ private boolean shouldInstrumentMethod(MethodNode method) { } private LogContextConfig resolveLogContextConfig(MethodNode method, AnnotationNode classAnnotation) { - AnnotationNode methodAnnotation = findAnnotation(method, LOG_CONTEXT_DESC); + AnnotationNode methodAnnotation = findAnnotation(method, DEBUG_LOG_DESC); if (methodAnnotation == null) { methodAnnotation = classAnnotation; } if (methodAnnotation == null) { return null; } - boolean lineHeatMap = getBooleanValue(methodAnnotation, "lineHeatMap", false); - boolean lineHeatMapOnException = getBooleanValue(methodAnnotation, "lineHeatMapOnException", false); - boolean subHeatMap = getBooleanValue(methodAnnotation, "subHeatMap", false); - boolean logDuration = getBooleanValue(methodAnnotation, "logDuration", false); - boolean aggregateChildren = getBooleanValue(methodAnnotation, "aggregateChildren", true); - boolean logArgs = getBooleanValue(methodAnnotation, "logArgs", true); - String mask = getStringValue(methodAnnotation, "mask", ""); - int maxArgLength = getIntValue(methodAnnotation, "maxArgLength", 200); - String logLevelName = getEnumValue(methodAnnotation, "logLevel", "DEBUG"); - String logFormatName = getEnumValue(methodAnnotation, "logFormat", "HUMAN"); - boolean logThreadId = getBooleanValue(methodAnnotation, "logThreadId", false); - boolean logThreadName = getBooleanValue(methodAnnotation, "logThreadName", false); + boolean lineHeatMap = resolveBoolean(methodAnnotation, "lineHeatMap", + DebugLogDefaults.DEFAULT_LINE_HEAT_MAP, defaults.getLineHeatMap()); + boolean lineHeatMapOnException = resolveBoolean(methodAnnotation, "lineHeatMapOnException", + DebugLogDefaults.DEFAULT_LINE_HEAT_MAP_ON_EXCEPTION, defaults.getLineHeatMapOnException()); + boolean subHeatMap = resolveBoolean(methodAnnotation, "subHeatMap", + DebugLogDefaults.DEFAULT_SUB_HEAT_MAP, defaults.getSubHeatMap()); + boolean logDuration = resolveBoolean(methodAnnotation, "logDuration", + DebugLogDefaults.DEFAULT_LOG_DURATION, defaults.getLogDuration()); + boolean aggregateChildren = resolveBoolean(methodAnnotation, "aggregateChildren", + DebugLogDefaults.DEFAULT_AGGREGATE_CHILDREN, defaults.getAggregateChildren()); + boolean logArgs = resolveBoolean(methodAnnotation, "logArgs", + DebugLogDefaults.DEFAULT_LOG_ARGS, defaults.getLogArgs()); + String mask = resolveString(methodAnnotation, "mask", + DebugLogDefaults.DEFAULT_MASK, defaults.getMask()); + int maxArgLength = resolveInt(methodAnnotation, "maxArgLength", + DebugLogDefaults.DEFAULT_MAX_ARG_LENGTH, defaults.getMaxArgLength()); + String logLevelName = resolveEnum(methodAnnotation, "logLevel", + DebugLogDefaults.DEFAULT_LOG_LEVEL.name(), defaults.getLogLevel()); + String logFormatName = resolveEnum(methodAnnotation, "logFormat", + DebugLogDefaults.DEFAULT_LOG_FORMAT.name(), defaults.getLogFormat()); + boolean logThreadId = resolveBoolean(methodAnnotation, "logThreadId", + DebugLogDefaults.DEFAULT_LOG_THREAD_ID, defaults.getLogThreadId()); + boolean logThreadName = resolveBoolean(methodAnnotation, "logThreadName", + DebugLogDefaults.DEFAULT_LOG_THREAD_NAME, defaults.getLogThreadName()); + boolean logLocals = resolveBoolean(methodAnnotation, "logLocals", + DebugLogDefaults.DEFAULT_LOG_LOCALS, defaults.getLogLocals()); + boolean logLocalsOnException = resolveBoolean(methodAnnotation, "logLocalsOnException", + DebugLogDefaults.DEFAULT_LOG_LOCALS_ON_EXCEPTION, defaults.getLogLocalsOnException()); if (lineHeatMapOnException) { lineHeatMap = true; } return new LogContextConfig(lineHeatMap, lineHeatMapOnException, subHeatMap, logDuration, aggregateChildren, logArgs, mask, maxArgLength, LogLevelConfig.fromName(logLevelName), - LogFormatConfig.fromName(logFormatName), logThreadId, logThreadName); + LogFormatConfig.fromName(logFormatName), logThreadId, logThreadName, logLocals, logLocalsOnException); + } + + private boolean resolveBoolean(AnnotationNode annotation, String name, boolean builtinDefault, Boolean override) { + boolean value = getBooleanValue(annotation, name, builtinDefault); + if (value == builtinDefault && override != null) { + return override; + } + return value; + } + + private int resolveInt(AnnotationNode annotation, String name, int builtinDefault, Integer override) { + int value = getIntValue(annotation, name, builtinDefault); + if (value == builtinDefault && override != null) { + return override; + } + return value; + } + + private String resolveString(AnnotationNode annotation, String name, String builtinDefault, String override) { + String value = getStringValue(annotation, name, builtinDefault); + if (builtinDefault.equals(value) && override != null) { + return override; + } + return value; + } + + private String resolveEnum(AnnotationNode annotation, String name, String builtinDefault, Enum override) { + String value = getEnumValue(annotation, name, builtinDefault); + if (builtinDefault.equals(value) && override != null) { + return override.name(); + } + return value; } private FieldNode findLoggerField(ClassNode classNode) { @@ -215,6 +277,10 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, List lineNumbers = config.lineHeatMap ? collectLineNumbers(method.instructions) : Collections.emptyList(); boolean hasHeatMap = config.lineHeatMap && !lineNumbers.isEmpty(); + int originalMaxLocals = method.maxLocals; + ParamLogConfig[] paramConfigs = buildParamConfigs(method, argTypes.length); + LocalLogConfig localLogConfig = buildLocalLogConfig(method, originalMaxLocals, config.logLocals || config.logLocalsOnException); + boolean enableLocalLogs = (config.logLocals || config.logLocalsOnException) && localLogConfig.hasAnnotations; int nextLocal = method.maxLocals; int linesVar = -1; @@ -235,8 +301,20 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, nextLocal += returnType.getSize(); } - int durationVar = nextLocal; - nextLocal += 2; + int localsSnapshotVar = -1; + int localsNamesVar = -1; + int localsIgnoreVar = -1; + int localsMaskFirstVar = -1; + int localsMaskLastVar = -1; + if (enableLocalLogs) { + localsSnapshotVar = nextLocal++; + localsNamesVar = nextLocal++; + localsIgnoreVar = nextLocal++; + localsMaskFirstVar = nextLocal++; + localsMaskLastVar = nextLocal++; + } + + int durationVar = startTimeVar; int exceptionVar = nextLocal; nextLocal += 1; @@ -252,14 +330,22 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, append(entry, buildLineArrayInit(lineNumbers, linesVar, countsVar)); insertLineCounters(method, lineNumbers, countsVar); append(entry, buildTraceEnter(classNode, method, traceVar, config.subHeatMap, config.aggregateChildren, - config.logArgs, config.mask, config.maxArgLength, config.logFormat, argTypes, argIndexes)); + config.logArgs, config.mask, config.maxArgLength, config.logFormat, argTypes, argIndexes, paramConfigs)); } entry.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); entry.add(new VarInsnNode(Opcodes.LSTORE, startTimeVar)); - append(entry, buildEntryLog(classNode, method, loggerField, config, argTypes, argIndexes)); + if (enableLocalLogs) { + append(entry, buildLocalLogInit(localLogConfig, originalMaxLocals, localsSnapshotVar, localsNamesVar, + localsIgnoreVar, localsMaskFirstVar, localsMaskLastVar)); + } + append(entry, buildEntryLog(classNode, method, loggerField, config, argTypes, argIndexes, paramConfigs)); entry.add(startLabel); method.instructions.insert(entry); + if (enableLocalLogs) { + insertLocalSnapshotUpdates(method, localLogConfig, localsSnapshotVar); + } + List returns = new ArrayList<>(); for (AbstractInsnNode insn = method.instructions.getFirst(); insn != null; insn = insn.getNext()) { int opcode = insn.getOpcode(); @@ -272,14 +358,16 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, InsnList exit = new InsnList(); int opcode = ret.getOpcode(); if (returnType.getSort() == Type.VOID) { - append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, null, null)); + append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, null, null, + localsSnapshotVar, localsNamesVar, localsIgnoreVar, localsMaskFirstVar, localsMaskLastVar, enableLocalLogs)); if (hasHeatMap) { append(exit, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, false)); } exit.add(new InsnNode(Opcodes.RETURN)); } else { exit.add(new VarInsnNode(returnType.getOpcode(Opcodes.ISTORE), returnVar)); - append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, returnType, returnVar)); + append(exit, buildExitLog(classNode, method, loggerField, config, startTimeVar, durationVar, returnType, returnVar, + localsSnapshotVar, localsNamesVar, localsIgnoreVar, localsMaskFirstVar, localsMaskLastVar, enableLocalLogs)); if (hasHeatMap) { append(exit, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, false)); } @@ -294,7 +382,9 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, handler.add(endLabel); handler.add(handlerLabel); handler.add(new VarInsnNode(Opcodes.ASTORE, exceptionVar)); - append(handler, buildErrorLog(classNode, method, loggerField, config, startTimeVar, durationVar, exceptionVar)); + append(handler, buildErrorLog(classNode, method, loggerField, config, startTimeVar, durationVar, exceptionVar, + argTypes, argIndexes, paramConfigs, localsSnapshotVar, localsNamesVar, localsIgnoreVar, + localsMaskFirstVar, localsMaskLastVar, enableLocalLogs)); if (hasHeatMap) { append(handler, buildHeatMapLog(classNode, method, loggerField, linesVar, countsVar, traceVar, config, durationVar, true)); } @@ -306,7 +396,7 @@ private void instrumentLogContextMethod(ClassNode classNode, MethodNode method, } private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode loggerField, - LogContextConfig config, Type[] argTypes, int[] argIndexes) { + LogContextConfig config, Type[] argTypes, int[] argIndexes, ParamLogConfig[] paramConfigs) { InsnList insns = new InsnList(); LabelNode skipLabel = new LabelNode(); @@ -321,7 +411,7 @@ private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode if (config.logFormat.jsonFormat) { insns.add(new LdcInsnNode("{\"type\":\"enter\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); } else { - insns.add(new LdcInsnNode("[LC] ENTER " + methodDisplay)); + insns.add(new LdcInsnNode("[KLB] ENTER " + methodDisplay)); } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); @@ -338,7 +428,7 @@ private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new LdcInsnNode(",\"args\":")); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); - append(insns, buildArgsArray(argTypes, argIndexes)); + append(insns, buildAnnotatedArgsArray(argTypes, argIndexes, paramConfigs, false, config.maxArgLength)); insns.add(new LdcInsnNode(config.mask)); insns.add(new LdcInsnNode(config.maxArgLength)); insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgsJson", @@ -361,7 +451,7 @@ private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new LdcInsnNode(" args=")); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); - append(insns, buildArgsArray(argTypes, argIndexes)); + append(insns, buildAnnotatedArgsArray(argTypes, argIndexes, paramConfigs, false, config.maxArgLength)); insns.add(new LdcInsnNode(config.mask)); insns.add(new LdcInsnNode(config.maxArgLength)); insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgs", @@ -385,7 +475,9 @@ private InsnList buildEntryLog(ClassNode classNode, MethodNode method, FieldNode private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode loggerField, LogContextConfig config, int startTimeVar, int durationVar, - Type returnType, Integer returnVar) { + Type returnType, Integer returnVar, int localsSnapshotVar, int localsNamesVar, + int localsIgnoreVar, int localsMaskFirstVar, int localsMaskLastVar, + boolean hasLocalAnnotations) { InsnList insns = new InsnList(); LabelNode skipLabel = new LabelNode(); @@ -405,7 +497,7 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode if (config.logFormat.jsonFormat) { insns.add(new LdcInsnNode("{\"type\":\"exit\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); } else { - insns.add(new LdcInsnNode("[LC] EXIT " + methodDisplay)); + insns.add(new LdcInsnNode("[KLB] EXIT " + methodDisplay)); } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); @@ -424,6 +516,22 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(J)Ljava/lang/StringBuilder;", false)); + if (config.logLocals && hasLocalAnnotations) { + insns.add(new LdcInsnNode(",\"locals\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsSnapshotVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsNamesVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsIgnoreVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskFirstVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskLastVar)); + insns.add(new InsnNode(Opcodes.ICONST_0)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatLocalsJson", + "([Ljava/lang/Object;[Ljava/lang/String;[I[I[IZI)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } insns.add(new LdcInsnNode(",\"result\":\"")); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); @@ -469,6 +577,25 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode "(Ljava/lang/Object;)Ljava/lang/String;", false)); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + if (config.logLocals && hasLocalAnnotations) { + insns.add(new LdcInsnNode(" locals={")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsSnapshotVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsNamesVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsIgnoreVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskFirstVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskLastVar)); + insns.add(new InsnNode(Opcodes.ICONST_0)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatLocalsHuman", + "([Ljava/lang/Object;[Ljava/lang/String;[I[I[IZI)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("}")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } } insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "toString", @@ -483,7 +610,10 @@ private InsnList buildExitLog(ClassNode classNode, MethodNode method, FieldNode } private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode loggerField, - LogContextConfig config, int startTimeVar, int durationVar, int exceptionVar) { + LogContextConfig config, int startTimeVar, int durationVar, int exceptionVar, + Type[] argTypes, int[] argIndexes, ParamLogConfig[] paramConfigs, + int localsSnapshotVar, int localsNamesVar, int localsIgnoreVar, + int localsMaskFirstVar, int localsMaskLastVar, boolean hasLocalAnnotations) { InsnList insns = new InsnList(); insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false)); insns.add(new VarInsnNode(Opcodes.LLOAD, startTimeVar)); @@ -496,7 +626,7 @@ private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode if (config.logFormat.jsonFormat) { insns.add(new LdcInsnNode("{\"type\":\"error\",\"method\":\"" + escapeJson(methodDisplay) + "\"")); } else { - insns.add(new LdcInsnNode("[LC] ERROR " + methodDisplay)); + insns.add(new LdcInsnNode("[KLB] ERROR " + methodDisplay)); } insns.add(new MethodInsnNode(Opcodes.INVOKESPECIAL, "java/lang/StringBuilder", "", "(Ljava/lang/String;)V", false)); @@ -515,6 +645,34 @@ private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(J)Ljava/lang/StringBuilder;", false)); + if (config.logArgs) { + insns.add(new LdcInsnNode(",\"args\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + append(insns, buildAnnotatedArgsArray(argTypes, argIndexes, paramConfigs, true, config.maxArgLength)); + insns.add(new LdcInsnNode(config.mask)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgsJson", + "([Ljava/lang/Object;Ljava/lang/String;I)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + if (hasLocalAnnotations && (config.logLocalsOnException || config.logLocals)) { + insns.add(new LdcInsnNode(",\"locals\":")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsSnapshotVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsNamesVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsIgnoreVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskFirstVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskLastVar)); + insns.add(new InsnNode(Opcodes.ICONST_1)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatLocalsJson", + "([Ljava/lang/Object;[Ljava/lang/String;[I[I[IZI)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } insns.add(new LdcInsnNode(",\"error\":\"")); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); @@ -542,7 +700,41 @@ private InsnList buildErrorLog(ClassNode classNode, MethodNode method, FieldNode insns.add(new VarInsnNode(Opcodes.LLOAD, durationVar)); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(J)Ljava/lang/StringBuilder;", false)); - insns.add(new LdcInsnNode("ns err=")); + insns.add(new LdcInsnNode("ns")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + if (config.logArgs) { + insns.add(new LdcInsnNode(" args=")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + append(insns, buildAnnotatedArgsArray(argTypes, argIndexes, paramConfigs, true, config.maxArgLength)); + insns.add(new LdcInsnNode(config.mask)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatArgs", + "([Ljava/lang/Object;Ljava/lang/String;I)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + if (hasLocalAnnotations && (config.logLocalsOnException || config.logLocals)) { + insns.add(new LdcInsnNode(" locals={")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsSnapshotVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsNamesVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsIgnoreVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskFirstVar)); + insns.add(new VarInsnNode(Opcodes.ALOAD, localsMaskLastVar)); + insns.add(new InsnNode(Opcodes.ICONST_1)); + insns.add(new LdcInsnNode(config.maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "formatLocalsHuman", + "([Ljava/lang/Object;[Ljava/lang/String;[I[I[IZI)Ljava/lang/String;", false)); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + insns.add(new LdcInsnNode("}")); + insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", + "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); + } + insns.add(new LdcInsnNode(" err=")); insns.add(new MethodInsnNode(Opcodes.INVOKEVIRTUAL, "java/lang/StringBuilder", "append", "(Ljava/lang/String;)Ljava/lang/StringBuilder;", false)); insns.add(new VarInsnNode(Opcodes.ALOAD, exceptionVar)); @@ -654,7 +846,8 @@ private void insertLineCounters(MethodNode method, List lineNumbers, in private InsnList buildTraceEnter(ClassNode classNode, MethodNode method, int traceVar, boolean subHeatMap, boolean aggregateChildren, boolean logArgs, String mask, int maxArgLength, - LogFormatConfig logFormat, Type[] argTypes, int[] argIndexes) { + LogFormatConfig logFormat, Type[] argTypes, int[] argIndexes, + ParamLogConfig[] paramConfigs) { InsnList insns = new InsnList(); String methodDescriptor = logFormat.jsonFormat ? buildMethodDescriptor(classNode, method) @@ -666,7 +859,7 @@ private InsnList buildTraceEnter(ClassNode classNode, MethodNode method, int tra insns.add(new LdcInsnNode(mask)); insns.add(new LdcInsnNode(maxArgLength)); if (logArgs) { - append(insns, buildArgsArray(argTypes, argIndexes)); + append(insns, buildAnnotatedArgsArray(argTypes, argIndexes, paramConfigs, false, maxArgLength)); } else { insns.add(new InsnNode(Opcodes.ACONST_NULL)); } @@ -711,6 +904,41 @@ private InsnList buildArgsArray(Type[] argTypes, int[] argIndexes) { return insns; } + private InsnList buildAnnotatedArgsArray(Type[] argTypes, int[] argIndexes, ParamLogConfig[] paramConfigs, + boolean forException, int maxArgLength) { + if (paramConfigs == null || paramConfigs.length == 0) { + return buildArgsArray(argTypes, argIndexes); + } + InsnList insns = new InsnList(); + pushInt(insns, argTypes.length); + insns.add(new TypeInsnNode(Opcodes.ANEWARRAY, "java/lang/Object")); + for (int i = 0; i < argTypes.length; i++) { + ParamLogConfig config = paramConfigs[i]; + insns.add(new InsnNode(Opcodes.DUP)); + pushInt(insns, i); + if (config != null && config.shouldIgnore(forException)) { + insns.add(new LdcInsnNode("***")); + insns.add(new InsnNode(Opcodes.AASTORE)); + continue; + } + if (config != null && config.hasMask()) { + insns.add(new VarInsnNode(argTypes[i].getOpcode(Opcodes.ILOAD), argIndexes[i])); + boxValue(insns, argTypes[i]); + insns.add(new LdcInsnNode(config.maskFirst)); + insns.add(new LdcInsnNode(config.maskLast)); + insns.add(new LdcInsnNode(maxArgLength)); + insns.add(new MethodInsnNode(Opcodes.INVOKESTATIC, "org/kolobok/runtime/LogContextTrace", "maskValue", + "(Ljava/lang/Object;III)Ljava/lang/String;", false)); + insns.add(new InsnNode(Opcodes.AASTORE)); + continue; + } + insns.add(new VarInsnNode(argTypes[i].getOpcode(Opcodes.ILOAD), argIndexes[i])); + boxValue(insns, argTypes[i]); + insns.add(new InsnNode(Opcodes.AASTORE)); + } + return insns; + } + private void boxValue(InsnList insns, Type type) { switch (type.getSort()) { case Type.BOOLEAN: @@ -774,6 +1002,220 @@ private int[] computeArgIndexes(boolean isStatic, Type[] argTypes) { return indexes; } + private ParamLogConfig[] buildParamConfigs(MethodNode method, int paramCount) { + ParamLogConfig[] configs = new ParamLogConfig[paramCount]; + List[] visible = method.visibleParameterAnnotations; + List[] invisible = method.invisibleParameterAnnotations; + for (int i = 0; i < paramCount; i++) { + ParamLogConfig config = new ParamLogConfig(); + boolean configured = false; + if (visible != null && i < visible.length) { + configured |= applyParamAnnotations(config, visible[i]); + } + if (invisible != null && i < invisible.length) { + configured |= applyParamAnnotations(config, invisible[i]); + } + configs[i] = configured ? config : null; + } + return configs; + } + + private boolean applyParamAnnotations(ParamLogConfig config, List annotations) { + if (annotations == null) { + return false; + } + boolean configured = false; + for (AnnotationNode annotation : annotations) { + if (DEBUG_LOG_IGNORE_DESC.equals(annotation.desc)) { + String mode = getEnumValue(annotation, "mode", "ALWAYS"); + config.ignoreMode = "SUCCESS".equalsIgnoreCase(mode) ? IgnoreMode.SUCCESS : IgnoreMode.ALWAYS; + configured = true; + } else if (DEBUG_LOG_MASK_DESC.equals(annotation.desc)) { + config.maskFirst = getIntValue(annotation, "first", 0); + config.maskLast = getIntValue(annotation, "last", 0); + configured = true; + } + } + return configured; + } + + private LocalLogConfig buildLocalLogConfig(MethodNode method, int localsSize, boolean includeAllLocals) { + LocalLogConfig config = new LocalLogConfig(localsSize); + config.includeAllLocals = includeAllLocals; + if (method.visibleLocalVariableAnnotations != null) { + applyLocalVariableAnnotations(config, method.visibleLocalVariableAnnotations); + } + if (method.invisibleLocalVariableAnnotations != null) { + applyLocalVariableAnnotations(config, method.invisibleLocalVariableAnnotations); + } + if (!config.hasAnnotations && !includeAllLocals) { + return config; + } + if (includeAllLocals) { + config.hasAnnotations = true; + } + config.names = new String[localsSize]; + config.ignoreModes = new int[localsSize]; + config.maskFirst = new int[localsSize]; + config.maskLast = new int[localsSize]; + if (includeAllLocals) { + for (int i = 0; i < localsSize; i++) { + config.names[i] = "var" + i; + } + } + if (method.localVariables != null) { + for (LocalVariableNode var : method.localVariables) { + if (var.index >= 0 && var.index < localsSize && config.hasIndex(var.index)) { + if (config.names[var.index] == null) { + config.names[var.index] = var.name; + } + } + } + } + for (LocalVarConfig entry : config.entries) { + int idx = entry.index; + if (idx >= 0 && idx < localsSize) { + if (config.names[idx] == null) { + config.names[idx] = "var" + idx; + } + config.ignoreModes[idx] = entry.ignoreMode == IgnoreMode.ALWAYS ? 1 + : entry.ignoreMode == IgnoreMode.SUCCESS ? 2 : 0; + config.maskFirst[idx] = entry.maskFirst; + config.maskLast[idx] = entry.maskLast; + } + } + return config; + } + + private void applyLocalVariableAnnotations(LocalLogConfig config, List annotations) { + for (LocalVariableAnnotationNode annotation : annotations) { + if (!DEBUG_LOG_IGNORE_DESC.equals(annotation.desc) && !DEBUG_LOG_MASK_DESC.equals(annotation.desc)) { + continue; + } + for (int index : annotation.index) { + LocalVarConfig entry = config.findOrCreate(index); + if (DEBUG_LOG_IGNORE_DESC.equals(annotation.desc)) { + String mode = getEnumValue(annotation, "mode", "ALWAYS"); + entry.ignoreMode = "SUCCESS".equalsIgnoreCase(mode) ? IgnoreMode.SUCCESS : IgnoreMode.ALWAYS; + } else if (DEBUG_LOG_MASK_DESC.equals(annotation.desc)) { + entry.maskFirst = getIntValue(annotation, "first", 0); + entry.maskLast = getIntValue(annotation, "last", 0); + } + config.hasAnnotations = true; + } + } + } + + private InsnList buildLocalLogInit(LocalLogConfig config, int localsSize, int snapshotVar, int namesVar, + int ignoreVar, int maskFirstVar, int maskLastVar) { + InsnList insns = new InsnList(); + pushInt(insns, localsSize); + insns.add(new TypeInsnNode(Opcodes.ANEWARRAY, "java/lang/Object")); + insns.add(new VarInsnNode(Opcodes.ASTORE, snapshotVar)); + pushInt(insns, localsSize); + insns.add(new TypeInsnNode(Opcodes.ANEWARRAY, "java/lang/String")); + insns.add(new VarInsnNode(Opcodes.ASTORE, namesVar)); + pushInt(insns, localsSize); + insns.add(new IntInsnNode(Opcodes.NEWARRAY, Opcodes.T_INT)); + insns.add(new VarInsnNode(Opcodes.ASTORE, ignoreVar)); + pushInt(insns, localsSize); + insns.add(new IntInsnNode(Opcodes.NEWARRAY, Opcodes.T_INT)); + insns.add(new VarInsnNode(Opcodes.ASTORE, maskFirstVar)); + pushInt(insns, localsSize); + insns.add(new IntInsnNode(Opcodes.NEWARRAY, Opcodes.T_INT)); + insns.add(new VarInsnNode(Opcodes.ASTORE, maskLastVar)); + + for (int i = 0; i < localsSize; i++) { + if (config.names == null || config.names.length <= i) { + continue; + } + String name = config.names[i]; + if (name != null) { + insns.add(new VarInsnNode(Opcodes.ALOAD, namesVar)); + pushInt(insns, i); + insns.add(new LdcInsnNode(name)); + insns.add(new InsnNode(Opcodes.AASTORE)); + } + int ignore = config.ignoreModes != null && config.ignoreModes.length > i ? config.ignoreModes[i] : 0; + int first = config.maskFirst != null && config.maskFirst.length > i ? config.maskFirst[i] : 0; + int last = config.maskLast != null && config.maskLast.length > i ? config.maskLast[i] : 0; + if (ignore != 0) { + insns.add(new VarInsnNode(Opcodes.ALOAD, ignoreVar)); + pushInt(insns, i); + pushInt(insns, ignore); + insns.add(new InsnNode(Opcodes.IASTORE)); + } + if (first != 0) { + insns.add(new VarInsnNode(Opcodes.ALOAD, maskFirstVar)); + pushInt(insns, i); + pushInt(insns, first); + insns.add(new InsnNode(Opcodes.IASTORE)); + } + if (last != 0) { + insns.add(new VarInsnNode(Opcodes.ALOAD, maskLastVar)); + pushInt(insns, i); + pushInt(insns, last); + insns.add(new InsnNode(Opcodes.IASTORE)); + } + } + return insns; + } + + private void insertLocalSnapshotUpdates(MethodNode method, LocalLogConfig config, int snapshotVar) { + for (AbstractInsnNode insn = method.instructions.getFirst(); insn != null; insn = insn.getNext()) { + if (insn instanceof VarInsnNode) { + VarInsnNode varInsn = (VarInsnNode) insn; + if (!config.hasIndex(varInsn.var)) { + continue; + } + int opcode = varInsn.getOpcode(); + if (opcode == Opcodes.ISTORE || opcode == Opcodes.ASTORE) { + InsnList update = new InsnList(); + update.add(new VarInsnNode(Opcodes.ALOAD, snapshotVar)); + pushInt(update, varInsn.var); + update.add(new VarInsnNode(opcodeToLoad(opcode), varInsn.var)); + boxValue(update, opcodeToType(opcode)); + update.add(new InsnNode(Opcodes.AASTORE)); + method.instructions.insert(varInsn, update); + } + } else if (insn.getOpcode() == Opcodes.IINC) { + IincInsnNode iinc = (IincInsnNode) insn; + if (!config.hasIndex(iinc.var)) { + continue; + } + InsnList update = new InsnList(); + update.add(new VarInsnNode(Opcodes.ALOAD, snapshotVar)); + pushInt(update, iinc.var); + update.add(new VarInsnNode(Opcodes.ILOAD, iinc.var)); + boxValue(update, Type.INT_TYPE); + update.add(new InsnNode(Opcodes.AASTORE)); + method.instructions.insert(iinc, update); + } + } + } + + private int opcodeToLoad(int storeOpcode) { + switch (storeOpcode) { + case Opcodes.ISTORE: + return Opcodes.ILOAD; + case Opcodes.ASTORE: + return Opcodes.ALOAD; + default: + return Opcodes.ALOAD; + } + } + + private Type opcodeToType(int storeOpcode) { + switch (storeOpcode) { + case Opcodes.ISTORE: + return Type.INT_TYPE; + case Opcodes.ASTORE: + return Type.getType(Object.class); + default: + return Type.getType(Object.class); + } + } + private String toHumanName(String internalName) { return internalName.replace('/', '.'); } @@ -1260,6 +1702,81 @@ private ParamInfo(int argIndex, Type type) { } } + private enum IgnoreMode { + NONE, + ALWAYS, + SUCCESS + } + + private static final class ParamLogConfig { + private IgnoreMode ignoreMode = IgnoreMode.NONE; + private int maskFirst; + private int maskLast; + + private boolean hasMask() { + return maskFirst > 0 || maskLast > 0; + } + + private boolean shouldIgnore(boolean forException) { + if (ignoreMode == IgnoreMode.ALWAYS) { + return true; + } + return ignoreMode == IgnoreMode.SUCCESS && !forException; + } + } + + private static final class LocalVarConfig { + private final int index; + private IgnoreMode ignoreMode = IgnoreMode.NONE; + private int maskFirst; + private int maskLast; + + private LocalVarConfig(int index) { + this.index = index; + } + } + + private static final class LocalLogConfig { + private final java.util.List entries = new java.util.ArrayList<>(); + private final int localsSize; + private boolean hasAnnotations; + private boolean includeAllLocals; + private String[] names; + private int[] ignoreModes; + private int[] maskFirst; + private int[] maskLast; + + private LocalLogConfig(int localsSize) { + this.localsSize = localsSize; + } + + private LocalVarConfig findOrCreate(int index) { + for (LocalVarConfig entry : entries) { + if (entry.index == index) { + return entry; + } + } + LocalVarConfig entry = new LocalVarConfig(index); + entries.add(entry); + return entry; + } + + private boolean hasIndex(int index) { + if (index < 0 || index >= localsSize) { + return false; + } + if (includeAllLocals) { + return true; + } + for (LocalVarConfig entry : entries) { + if (entry.index == index) { + return true; + } + } + return false; + } + } + private static class LogContextConfig { private final boolean lineHeatMap; private final boolean lineHeatMapOnException; @@ -1273,11 +1790,13 @@ private static class LogContextConfig { private final LogFormatConfig logFormat; private final boolean logThreadId; private final boolean logThreadName; + private final boolean logLocals; + private final boolean logLocalsOnException; private LogContextConfig(boolean lineHeatMap, boolean lineHeatMapOnException, boolean subHeatMap, boolean logDuration, boolean aggregateChildren, boolean logArgs, String mask, int maxArgLength, LogLevelConfig logLevel, LogFormatConfig logFormat, - boolean logThreadId, boolean logThreadName) { + boolean logThreadId, boolean logThreadName, boolean logLocals, boolean logLocalsOnException) { this.lineHeatMap = lineHeatMap; this.lineHeatMapOnException = lineHeatMapOnException; this.subHeatMap = subHeatMap; @@ -1290,6 +1809,8 @@ private LogContextConfig(boolean lineHeatMap, boolean lineHeatMapOnException, bo this.logFormat = logFormat; this.logThreadId = logThreadId; this.logThreadName = logThreadName; + this.logLocals = logLocals; + this.logLocalsOnException = logLocalsOnException; } } diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java index e506d36..f88be83 100644 --- a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextHeatMapIntegrationTest.java @@ -58,14 +58,14 @@ private void writeSources(Path srcDir) throws IOException { String service = String.join("\n", "package sample;", "", - "import org.kolobok.annotation.LogContext;", + "import org.kolobok.annotation.DebugLog;", "import org.slf4j.Logger;", "import org.slf4j.LoggerFactory;", "", "public class SampleService {", " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", "", - " @LogContext(lineHeatMap = true, logDuration = true)", + " @DebugLog(lineHeatMap = true, logDuration = true)", " public void work() {", " if (System.currentTimeMillis() > 0) {", " return;", diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java index 9377c85..6e7b95b 100644 --- a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextIntegrationTest.java @@ -53,14 +53,14 @@ private void writeSources(Path srcDir) throws IOException { String service = String.join("\n", "package sample;", "", - "import org.kolobok.annotation.LogContext;", + "import org.kolobok.annotation.DebugLog;", "import org.slf4j.Logger;", "import org.slf4j.LoggerFactory;", "", "public class SampleService {", " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", "", - " @LogContext", + " @DebugLog", " public String work(String name, int count) {", " return name + count;", " }", diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java index 3b59af5..bdb59a3 100644 --- a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLineNumberTest.java @@ -60,14 +60,14 @@ private int writeSources(Path srcDir) throws IOException { String[] lines = new String[]{ "package sample;", "", - "import org.kolobok.annotation.LogContext;", + "import org.kolobok.annotation.DebugLog;", "import org.slf4j.Logger;", "import org.slf4j.LoggerFactory;", "", "public class SampleService {", " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", "", - " @LogContext", + " @DebugLog", " public void explode() {", " throw new IllegalStateException(\"boom\");", " }", diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsHumanIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsHumanIntegrationTest.java new file mode 100644 index 0000000..f1e9cbe --- /dev/null +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsHumanIntegrationTest.java @@ -0,0 +1,119 @@ +package org.kolobok.transformer; + +import org.junit.Test; +import org.objectweb.asm.ClassReader; +import org.objectweb.asm.tree.ClassNode; +import org.objectweb.asm.tree.MethodInsnNode; +import org.objectweb.asm.tree.MethodNode; + +import javax.tools.Diagnostic; +import javax.tools.DiagnosticCollector; +import javax.tools.JavaCompiler; +import javax.tools.JavaFileObject; +import javax.tools.StandardJavaFileManager; +import javax.tools.ToolProvider; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.List; +import java.util.Optional; + +import static org.assertj.core.api.Assertions.assertThat; + +public class LogContextLocalsHumanIntegrationTest { + + @Test + public void instrumentsLocalsInHumanFormat() throws Exception { + Path tempDir = Files.createTempDirectory("kolobok-log-locals-human"); + Path srcDir = tempDir.resolve("src"); + Path classesDir = tempDir.resolve("classes"); + Files.createDirectories(srcDir.resolve("sample")); + Files.createDirectories(classesDir); + + writeSources(srcDir); + compileSources(srcDir, classesDir); + + Path classFile = classesDir.resolve("sample/SampleService.class"); + KolobokTransformer transformer = new KolobokTransformer(); + transformer.transformClassFile(classFile); + + ClassNode classNode = readClassNode(classFile); + MethodNode work = findMethod(classNode, "work", "(Ljava/lang/String;)Ljava/lang/String;"); + assertThat(work).isNotNull(); + + boolean hasLocalsHuman = Arrays.stream(work.instructions.toArray()) + .filter(node -> node instanceof MethodInsnNode) + .map(node -> (MethodInsnNode) node) + .anyMatch(node -> "org/kolobok/runtime/LogContextTrace".equals(node.owner) + && "formatLocalsHuman".equals(node.name)); + assertThat(hasLocalsHuman).isTrue(); + } + + private void writeSources(Path srcDir) throws IOException { + String service = String.join("\n", + "package sample;", + "", + "import org.kolobok.annotation.DebugLog;", + "import org.slf4j.Logger;", + "import org.slf4j.LoggerFactory;", + "", + "public class SampleService {", + " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", + "", + " @DebugLog(logLocals = true)", + " public String work(String input) {", + " int len = input == null ? 0 : input.length();", + " String tag = \"x\" + len;", + " return tag;", + " }", + "}", + "" + ); + Files.writeString(srcDir.resolve("sample/SampleService.java"), service); + } + + private void compileSources(Path srcDir, Path classesDir) throws IOException { + JavaCompiler compiler = ToolProvider.getSystemJavaCompiler(); + assertThat(compiler).as("System Java compiler is available").isNotNull(); + + DiagnosticCollector diagnostics = new DiagnosticCollector<>(); + StandardJavaFileManager fileManager = compiler.getStandardFileManager(diagnostics, null, null); + Iterable units = fileManager.getJavaFileObjectsFromFiles( + Arrays.asList(srcDir.resolve("sample/SampleService.java").toFile()) + ); + + List options = Arrays.asList( + "-g", + "-d", classesDir.toString(), + "-classpath", System.getProperty("java.class.path") + ); + + Boolean result = compiler.getTask(null, fileManager, diagnostics, options, null, units).call(); + fileManager.close(); + + if (result == null || !result) { + StringBuilder sb = new StringBuilder("Compilation failed:\n"); + for (Diagnostic diagnostic : diagnostics.getDiagnostics()) { + sb.append(diagnostic.getKind()).append(": ") + .append(diagnostic.getMessage(null)).append("\n"); + } + throw new IllegalStateException(sb.toString()); + } + } + + private ClassNode readClassNode(Path classFile) throws IOException { + byte[] bytes = Files.readAllBytes(classFile); + ClassReader reader = new ClassReader(bytes); + ClassNode node = new ClassNode(); + reader.accept(node, ClassReader.SKIP_DEBUG | ClassReader.SKIP_FRAMES); + return node; + } + + private MethodNode findMethod(ClassNode classNode, String name, String desc) { + Optional method = classNode.methods.stream() + .filter(m -> m.name.equals(name) && m.desc.equals(desc)) + .findFirst(); + return method.orElse(null); + } +} diff --git a/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsIntegrationTest.java b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsIntegrationTest.java new file mode 100644 index 0000000..ab6a986 --- /dev/null +++ b/kolobok-transformer/src/test/java/org/kolobok/transformer/LogContextLocalsIntegrationTest.java @@ -0,0 +1,123 @@ +package org.kolobok.transformer; + +import org.junit.Test; +import org.objectweb.asm.ClassReader; +import org.objectweb.asm.tree.ClassNode; +import org.objectweb.asm.tree.MethodInsnNode; +import org.objectweb.asm.tree.MethodNode; + +import javax.tools.Diagnostic; +import javax.tools.DiagnosticCollector; +import javax.tools.JavaCompiler; +import javax.tools.JavaFileObject; +import javax.tools.StandardJavaFileManager; +import javax.tools.ToolProvider; +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.List; +import java.util.Optional; + +import static org.assertj.core.api.Assertions.assertThat; + +public class LogContextLocalsIntegrationTest { + + @Test + public void instrumentsLocalsOnException() throws Exception { + Path tempDir = Files.createTempDirectory("kolobok-log-locals"); + Path srcDir = tempDir.resolve("src"); + Path classesDir = tempDir.resolve("classes"); + Files.createDirectories(srcDir.resolve("sample")); + Files.createDirectories(classesDir); + + writeSources(srcDir); + compileSources(srcDir, classesDir); + + Path classFile = classesDir.resolve("sample/SampleService.class"); + KolobokTransformer transformer = new KolobokTransformer(); + transformer.transformClassFile(classFile); + + ClassNode classNode = readClassNode(classFile); + MethodNode work = findMethod(classNode, "work", "(Ljava/lang/String;)Ljava/lang/String;"); + assertThat(work).isNotNull(); + + boolean hasLocalsJson = Arrays.stream(work.instructions.toArray()) + .filter(node -> node instanceof MethodInsnNode) + .map(node -> (MethodInsnNode) node) + .anyMatch(node -> "org/kolobok/runtime/LogContextTrace".equals(node.owner) + && "formatLocalsJson".equals(node.name)); + assertThat(hasLocalsJson).isTrue(); + } + + private void writeSources(Path srcDir) throws IOException { + String service = String.join("\n", + "package sample;", + "", + "import org.kolobok.annotation.DebugLog;", + "import org.kolobok.annotation.DebugLog.LogFormat;", + "import org.slf4j.Logger;", + "import org.slf4j.LoggerFactory;", + "", + "public class SampleService {", + " private static final Logger log = LoggerFactory.getLogger(SampleService.class);", + "", + " @DebugLog(logLocalsOnException = true, logFormat = LogFormat.JSON)", + " public String work(String input) {", + " int len = input == null ? 0 : input.length();", + " String tag = \"x\" + len;", + " if (len == 5) {", + " throw new IllegalArgumentException(\"boom\");", + " }", + " return tag;", + " }", + "}", + "" + ); + Files.writeString(srcDir.resolve("sample/SampleService.java"), service); + } + + private void compileSources(Path srcDir, Path classesDir) throws IOException { + JavaCompiler compiler = ToolProvider.getSystemJavaCompiler(); + assertThat(compiler).as("System Java compiler is available").isNotNull(); + + DiagnosticCollector diagnostics = new DiagnosticCollector<>(); + StandardJavaFileManager fileManager = compiler.getStandardFileManager(diagnostics, null, null); + Iterable units = fileManager.getJavaFileObjectsFromFiles( + Arrays.asList(srcDir.resolve("sample/SampleService.java").toFile()) + ); + + List options = Arrays.asList( + "-g", + "-d", classesDir.toString(), + "-classpath", System.getProperty("java.class.path") + ); + + Boolean result = compiler.getTask(null, fileManager, diagnostics, options, null, units).call(); + fileManager.close(); + + if (result == null || !result) { + StringBuilder sb = new StringBuilder("Compilation failed:\n"); + for (Diagnostic diagnostic : diagnostics.getDiagnostics()) { + sb.append(diagnostic.getKind()).append(": ") + .append(diagnostic.getMessage(null)).append("\n"); + } + throw new IllegalStateException(sb.toString()); + } + } + + private ClassNode readClassNode(Path classFile) throws IOException { + byte[] bytes = Files.readAllBytes(classFile); + ClassReader reader = new ClassReader(bytes); + ClassNode node = new ClassNode(); + reader.accept(node, ClassReader.SKIP_DEBUG | ClassReader.SKIP_FRAMES); + return node; + } + + private MethodNode findMethod(ClassNode classNode, String name, String desc) { + Optional method = classNode.methods.stream() + .filter(m -> m.name.equals(name) && m.desc.equals(desc)) + .findFirst(); + return method.orElse(null); + } +} diff --git a/pom.xml b/pom.xml index 9bd146d..d33f491 100644 --- a/pom.xml +++ b/pom.xml @@ -6,7 +6,7 @@ com.github.ukman kolobok-parent - 0.2.3 + 0.2.4 pom Kolobok Parent diff --git a/samples/spring-data-jpa-gradle/build.gradle b/samples/spring-data-jpa-gradle/build.gradle index d238fd1..f777772 100644 --- a/samples/spring-data-jpa-gradle/build.gradle +++ b/samples/spring-data-jpa-gradle/build.gradle @@ -4,7 +4,7 @@ buildscript { mavenCentral() } dependencies { - classpath 'com.github.ukman:kolobok-gradle-plugin:0.2.3' + classpath 'com.github.ukman:kolobok-gradle-plugin:0.2.4' } } @@ -34,7 +34,11 @@ dependencies { implementation 'org.springframework.boot:spring-boot-starter-data-jpa' implementation 'org.springdoc:springdoc-openapi-ui:1.7.0' runtimeOnly 'com.h2database:h2' - compileOnly 'com.github.ukman:kolobok:0.2.3' + implementation 'com.github.ukman:kolobok:0.2.4' + compileOnly 'org.projectlombok:lombok:1.18.32' + annotationProcessor 'org.projectlombok:lombok:1.18.32' + testCompileOnly 'org.projectlombok:lombok:1.18.32' + testAnnotationProcessor 'org.projectlombok:lombok:1.18.32' testImplementation 'org.springframework.boot:spring-boot-starter-test' } diff --git a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/Person.java b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/Person.java index 1192851..bb3d168 100644 --- a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/Person.java +++ b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/Person.java @@ -4,8 +4,14 @@ import javax.persistence.GeneratedValue; import javax.persistence.GenerationType; import javax.persistence.Id; +import lombok.AllArgsConstructor; +import lombok.Data; +import lombok.NoArgsConstructor; @Entity +@Data +@NoArgsConstructor +@AllArgsConstructor public class Person { @Id @GeneratedValue(strategy = GenerationType.IDENTITY) @@ -16,46 +22,4 @@ public class Person { private String lastName; private String title; - - public Person() { - } - - public Person(Long id, String firstName, String lastName, String title) { - this.id = id; - this.firstName = firstName; - this.lastName = lastName; - this.title = title; - } - - public Long getId() { - return id; - } - - public void setId(Long id) { - this.id = id; - } - - public String getFirstName() { - return firstName; - } - - public void setFirstName(String firstName) { - this.firstName = firstName; - } - - public String getLastName() { - return lastName; - } - - public void setLastName(String lastName) { - this.lastName = lastName; - } - - public String getTitle() { - return title; - } - - public void setTitle(String title) { - this.title = title; - } } diff --git a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonController.java b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonController.java index 531af77..d6acca1 100644 --- a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonController.java +++ b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonController.java @@ -3,6 +3,8 @@ import io.swagger.v3.oas.annotations.Operation; import io.swagger.v3.oas.annotations.Parameter; import io.swagger.v3.oas.annotations.tags.Tag; +import lombok.extern.slf4j.Slf4j; +import org.kolobok.annotation.DebugLog; import org.springframework.http.HttpStatus; import org.springframework.http.ResponseEntity; import org.springframework.web.bind.annotation.*; @@ -12,6 +14,7 @@ @RestController @RequestMapping("/persons") @Tag(name = "Persons", description = "CRUD operations for persons") +@Slf4j public class PersonController { private final PersonService service; @@ -55,11 +58,15 @@ public ResponseEntity delete(@Parameter(description = "Person id") @PathVa @Operation(summary = "Search persons by optional firstName/lastName/title") @GetMapping("/search") + @DebugLog(lineHeatMap = true) public List search( @Parameter(description = "First name") @RequestParam(required = false) String firstName, @Parameter(description = "Last name") @RequestParam(required = false) String lastName, @Parameter(description = "Title") @RequestParam(required = false) String title ) { + if ("error".equals(firstName)) { + throw new RuntimeException("Simulated error"); + } return service.search(firstName, lastName, title); } } diff --git a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonService.java b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonService.java index 0b32f0d..d7fad92 100644 --- a/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonService.java +++ b/samples/spring-data-jpa-gradle/src/main/java/com/example/kolobok/PersonService.java @@ -1,15 +1,19 @@ package com.example.kolobok; +import lombok.extern.slf4j.Slf4j; +import org.kolobok.annotation.DebugLog; import org.springframework.stereotype.Service; import org.springframework.web.server.ResponseStatusException; import java.util.ArrayList; import java.util.List; +import java.util.stream.Collectors; import java.util.stream.StreamSupport; import static org.springframework.http.HttpStatus.NOT_FOUND; @Service +@Slf4j public class PersonService { private final PersonRepository repository; @@ -35,7 +39,6 @@ public Person update(Long id, Person update) { Person existing = get(id); existing.setFirstName(update.getFirstName()); existing.setLastName(update.getLastName()); - existing.setTitle(update.getTitle()); return repository.save(existing); } @@ -46,11 +49,29 @@ public void delete(Long id) { repository.deleteById(id); } + @DebugLog(lineHeatMap = true, subHeatMap=true, logDuration = true, logLocalsOnException = true) public List search(String firstName, String lastName, String title) { + log.info("Searching for persons with firstName: {}, lastName: {}, title: {}", firstName, lastName, title); + List res; + int a = firstName == null ? 0 : firstName.length(); + int b = lastName == null ? 0 : lastName.length(); + if (a + b == 5) { + throw new IllegalArgumentException("Wrong params"); + } if (title == null) { - return repository.findByFirstNameAndLastName(firstName, lastName); + res = repository.findByFirstNameAndLastName(firstName, lastName); + } else { + res = repository.findByFirstNameAndLastNameAndTitle(firstName, lastName, title); } - return repository.findByFirstNameAndLastNameAndTitle(firstName, lastName, title); + res = res.stream().map(p -> findById(p.getId())).collect(Collectors.toList()); + return res; + } + + @DebugLog(lineHeatMap = true, subHeatMap=true, logDuration = true) + public Person findById(Long id) { + Person res = repository.findById(id) + .orElseThrow(() -> new ResponseStatusException(NOT_FOUND, "Person not found")); + return res; } private List toList(Iterable iterable) { diff --git a/samples/spring-data-jpa-gradle/src/main/resources/application.properties b/samples/spring-data-jpa-gradle/src/main/resources/application.properties index b3bba37..08d0534 100644 --- a/samples/spring-data-jpa-gradle/src/main/resources/application.properties +++ b/samples/spring-data-jpa-gradle/src/main/resources/application.properties @@ -1,2 +1,4 @@ spring.jpa.hibernate.ddl-auto=update spring.jpa.defer-datasource-initialization=true +logging.level.root=INFO +logging.level.com.example.kolobok=DEBUG diff --git a/samples/spring-data-jpa-maven/pom.xml b/samples/spring-data-jpa-maven/pom.xml index 39bc9bc..cf3edde 100644 --- a/samples/spring-data-jpa-maven/pom.xml +++ b/samples/spring-data-jpa-maven/pom.xml @@ -43,8 +43,7 @@ com.github.ukman kolobok - 0.2.3 - provided + 0.2.4 org.springframework.boot @@ -63,7 +62,7 @@ com.github.ukman kolobok-maven-plugin - 0.2.3 + 0.2.4 diff --git a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java index 9ac54fa..4f27437 100644 --- a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java +++ b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonController.java @@ -4,7 +4,7 @@ import io.swagger.v3.oas.annotations.Parameter; import io.swagger.v3.oas.annotations.tags.Tag; import lombok.extern.slf4j.Slf4j; -import org.kolobok.annotation.LogContext; +import org.kolobok.annotation.DebugLog; import org.springframework.http.HttpStatus; import org.springframework.http.ResponseEntity; import org.springframework.web.bind.annotation.*; @@ -58,7 +58,7 @@ public ResponseEntity delete(@Parameter(description = "Person id") @PathVa @Operation(summary = "Search persons by optional firstName/lastName") @GetMapping("/search") - @LogContext + @DebugLog(lineHeatMap = true) public List search( @Parameter(description = "First name") @RequestParam(required = false) String firstName, @Parameter(description = "Last name") @RequestParam(required = false) String lastName, diff --git a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonService.java b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonService.java index de9e8b3..eb69ec9 100644 --- a/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonService.java +++ b/samples/spring-data-jpa-maven/src/main/java/com/example/kolobok/PersonService.java @@ -5,11 +5,15 @@ import java.util.ArrayList; import java.util.List; +import java.util.stream.Collectors; import java.util.stream.StreamSupport; import static org.springframework.http.HttpStatus.NOT_FOUND; +import org.kolobok.annotation.DebugLog; +import lombok.extern.slf4j.Slf4j; @Service +@Slf4j public class PersonService { private final PersonRepository repository; @@ -45,11 +49,29 @@ public void delete(Long id) { repository.deleteById(id); } + @DebugLog(lineHeatMap = true, subHeatMap=true, logDuration = true, logLocalsOnException = true) public List search(String firstName, String lastName, String title) { + log.info("Searching for persons with firstName: {}, lastName: {}, title: {}", firstName, lastName, title); + List res; + int a = firstName == null ? 0 : firstName.length(); + int b = lastName == null ? 0 : lastName.length(); + if(a + b == 5) { + throw new IllegalArgumentException("Wrong params"); + } if (title == null) { - return repository.findByFirstNameAndLastName(firstName, lastName); + res = repository.findByFirstNameAndLastName(firstName, lastName); + } else { + res = repository.findByFirstNameAndLastNameAndTitle(firstName, lastName, title); } - return repository.findByFirstNameAndLastNameAndTitle(firstName, lastName, title); + res = res.stream().map(p -> findById(p.getId())).collect(Collectors.toList()); + return res; + } + + @DebugLog(lineHeatMap = true, subHeatMap=true, logDuration = true) + public Person findById(Long id) { + Person res = repository.findById(id) + .orElseThrow(() -> new ResponseStatusException(NOT_FOUND, "Person not found")); + return res; } private List toList(Iterable iterable) { diff --git a/samples/spring-data-jpa-maven/src/main/resources/application.properties b/samples/spring-data-jpa-maven/src/main/resources/application.properties index b3bba37..08d0534 100644 --- a/samples/spring-data-jpa-maven/src/main/resources/application.properties +++ b/samples/spring-data-jpa-maven/src/main/resources/application.properties @@ -1,2 +1,4 @@ spring.jpa.hibernate.ddl-auto=update spring.jpa.defer-datasource-initialization=true +logging.level.root=INFO +logging.level.com.example.kolobok=DEBUG