Simplify logging using static invocations and bytecode transformation

bom/application/pom.xml

@@ -17,7 +17,7 @@
         <bouncycastle.version>1.69</bouncycastle.version>
         <bouncycastle.fips.version>1.0.2.1</bouncycastle.fips.version>
         <bouncycastle.tls.fips.version>1.0.12.2</bouncycastle.tls.fips.version>
-        <jandex.version>2.3.1.Final</jandex.version>
+        <jandex.version>2.4.0.Final</jandex.version>
         <resteasy.version>4.7.0.Final</resteasy.version>
         <opentracing.version>0.33.0</opentracing.version>
         <opentracing-jaxrs.version>1.0.0</opentracing-jaxrs.version>
@@ -4365,6 +4365,11 @@
                 <artifactId>asm-analysis</artifactId>
                 <version>${asm.version}</version>
             </dependency>
+            <dependency>
+                <groupId>org.ow2.asm</groupId>
+                <artifactId>asm-commons</artifactId>
+                <version>${asm.version}</version>
+            </dependency>
             <dependency>
                 <groupId>org.slf4j</groupId>
                 <artifactId>slf4j-api</artifactId>

build-parent/pom.xml

@@ -34,7 +34,7 @@
         <failsafe-plugin.version>${version.surefire.plugin}</failsafe-plugin.version>
 
         <!-- jandex maven plugin version -->
-        <jandex-maven-plugin.version>1.1.1</jandex-maven-plugin.version>
+        <jandex-maven-plugin.version>1.2.0</jandex-maven-plugin.version>
 
         <!-- These properties are needed in order for them to be resolvable by the documentation -->
         <!-- The Graal version we suggest using in documentation - as that's

core/deployment/pom.xml

@@ -38,6 +38,10 @@
             <groupId>org.ow2.asm</groupId>
             <artifactId>asm</artifactId>
         </dependency>
+        <dependency>
+            <groupId>org.ow2.asm</groupId>
+            <artifactId>asm-commons</artifactId>
+        </dependency>
         <dependency>
             <groupId>io.quarkus</groupId>
             <artifactId>quarkus-development-mode-spi</artifactId>

core/deployment/src/main/java/io/quarkus/deployment/builditem/BytecodeTransformerBuildItem.java

@@ -40,6 +40,8 @@ public final class BytecodeTransformerBuildItem extends MultiBuildItem {
 
     final boolean cacheable;
 
+    final int classReaderOptions;
+
     public BytecodeTransformerBuildItem(String classToTransform,
             BiFunction<String, ClassVisitor, ClassVisitor> visitorFunction) {
         this(classToTransform, visitorFunction, null);
@@ -75,6 +77,7 @@ public BytecodeTransformerBuildItem(boolean eager, String classToTransform,
         this.requireConstPoolEntry = requireConstPoolEntry;
         this.cacheable = cacheable;
         this.inputTransformer = null;
+        this.classReaderOptions = 0;
     }
 
     public BytecodeTransformerBuildItem(Builder builder) {
@@ -84,6 +87,7 @@ public BytecodeTransformerBuildItem(Builder builder) {
         this.requireConstPoolEntry = builder.requireConstPoolEntry;
         this.cacheable = builder.cacheable;
         this.inputTransformer = builder.inputTransformer;
+        this.classReaderOptions = builder.classReaderOptions;
         if (visitorFunction == null && inputTransformer == null) {
             throw new IllegalArgumentException("One of either visitorFunction or inputTransformer must be set");
         }
@@ -109,6 +113,10 @@ public boolean isCacheable() {
         return cacheable;
     }
 
+    public int getClassReaderOptions() {
+        return classReaderOptions;
+    }
+
     public BiFunction<String, byte[], byte[]> getInputTransformer() {
         return inputTransformer;
     }
@@ -120,6 +128,7 @@ public static class Builder {
         private Set<String> requireConstPoolEntry = null;
         private boolean eager = false;
         private boolean cacheable = false;
+        private int classReaderOptions = 0;
 
         public Builder setInputTransformer(BiFunction<String, byte[], byte[]> inputTransformer) {
             this.inputTransformer = inputTransformer;
@@ -151,6 +160,11 @@ public Builder setCacheable(boolean cacheable) {
             return this;
         }
 
+        public Builder setClassReaderOptions(int classReaderOptions) {
+            this.classReaderOptions = classReaderOptions;
+            return this;
+        }
+
         public BytecodeTransformerBuildItem build() {
             return new BytecodeTransformerBuildItem(this);
         }

core/deployment/src/main/java/io/quarkus/deployment/index/IndexWrapper.java

@@ -19,6 +19,7 @@
 import org.jboss.jandex.Index;
 import org.jboss.jandex.IndexView;
 import org.jboss.jandex.Indexer;
+import org.jboss.jandex.ModuleInfo;
 import org.jboss.jandex.Type;
 import org.jboss.logging.Logger;
 
@@ -139,6 +140,21 @@ public Collection<AnnotationInstance> getAnnotationsWithRepeatable(DotName annot
         return this.index.getAnnotationsWithRepeatable(annotationName, index);
     }
 
+    @Override
+    public Collection<ModuleInfo> getKnownModules() {
+        return this.index.getKnownModules();
+    }
+
+    @Override
+    public ModuleInfo getModuleByName(DotName moduleName) {
+        return this.index.getModuleByName(moduleName);
+    }
+
+    @Override
+    public Collection<ClassInfo> getKnownUsers(DotName className) {
+        return this.index.getKnownUsers(className);
+    }
+
     private void getAllKnownSubClasses(DotName className, Set<ClassInfo> allKnown, Set<DotName> processedClasses) {
         final Set<DotName> subClassesToProcess = new HashSet<DotName>();
         subClassesToProcess.add(className);

core/deployment/src/main/java/io/quarkus/deployment/logging/LoggingWithPanacheProcessor.java

@@ -0,0 +1,198 @@
+package io.quarkus.deployment.logging;
+
+import org.jboss.jandex.ClassInfo;
+import org.jboss.jandex.DotName;
+import org.objectweb.asm.ClassReader;
+import org.objectweb.asm.ClassVisitor;
+import org.objectweb.asm.FieldVisitor;
+import org.objectweb.asm.MethodVisitor;
+import org.objectweb.asm.Opcodes;
+import org.objectweb.asm.Type;
+import org.objectweb.asm.commons.LocalVariablesSorter;
+
+import io.quarkus.deployment.annotations.BuildProducer;
+import io.quarkus.deployment.annotations.BuildStep;
+import io.quarkus.deployment.builditem.BytecodeTransformerBuildItem;
+import io.quarkus.deployment.builditem.CombinedIndexBuildItem;
+import io.quarkus.gizmo.Gizmo;
+
+public class LoggingWithPanacheProcessor {
+    private static final DotName QUARKUS_LOG_DOTNAME = DotName.createSimple("io.quarkus.logging.Log");
+
+    private static final String QUARKUS_LOG_BINARY_NAME = "io/quarkus/logging/Log";
+
+    private static final String SYNTHETIC_LOGGER_FIELD_NAME = "quarkusSyntheticLogger";
+
+    private static final String JBOSS_LOGGER_BINARY_NAME = "org/jboss/logging/Logger";
+    private static final String JBOSS_LOGGER_DESCRIPTOR = "L" + JBOSS_LOGGER_BINARY_NAME + ";";
+    private static final String GET_LOGGER_DESCRIPTOR = "(Ljava/lang/String;)" + JBOSS_LOGGER_DESCRIPTOR;
+
+    @BuildStep
+    public void process(CombinedIndexBuildItem index, BuildProducer<BytecodeTransformerBuildItem> transformers) {
+        for (ClassInfo clazz : index.getIndex().getKnownUsers(QUARKUS_LOG_DOTNAME)) {
+            String className = clazz.name().toString();
+
+            transformers.produce(new BytecodeTransformerBuildItem.Builder()
+                    .setClassToTransform(className)
+                    .setVisitorFunction((ignored, visitor) -> new AddLoggerFieldAndRewriteInvocations(visitor, className))
+                    .setClassReaderOptions(ClassReader.EXPAND_FRAMES)
+                    .build());
+        }
+    }
+
+    /**
+     * Makes the following modifications to the visited class:
+     * <ul>
+     * <li>adds a {@code private static final} field of type {@code org.jboss.logging.Logger};</li>
+     * <li>initializes the field (to {@code Logger.getLogger(className)}) at the beginning of the
+     * static initializer (creating one if missing);</li>
+     * <li>rewrites all invocations of {@code static} methods on {@code io.quarkus.logging.Log}
+     * to corresponding invocations of virtual methods on the logger field.</li>
+     * </ul>
+     * Assumes that the set of {@code static} methods on {@code io.quarkus.runtime.logging.Log}
+     * is identical (when it comes to names, return types and parameter types) to the set of virtual methods
+     * on {@code org.jboss.logging.BasicLogger}.
+     */
+    private static class AddLoggerFieldAndRewriteInvocations extends ClassVisitor {
+        private final String className;
+        private final String classNameBinary;
+
+        private boolean generatedLoggerField;
+        private boolean generatedLoggerFieldInitialization;
+
+        public AddLoggerFieldAndRewriteInvocations(ClassVisitor visitor, String className) {
+            super(Gizmo.ASM_API_VERSION, visitor);
+            this.className = className;
+            this.classNameBinary = className.replace(".", "/");
+        }
+
+        @Override
+        public FieldVisitor visitField(int access, String name, String descriptor, String signature, Object value) {
+            if (!generatedLoggerField) {
+                // should be the first field
+                // if there's no field, this will be called in visitEnd
+                generateLoggerField();
+            }
+
+            return super.visitField(access, name, descriptor, signature, value);
+        }
+
+        @Override
+        public MethodVisitor visitMethod(int access, String name, String descriptor, String signature, String[] exceptions) {
+            MethodVisitor visitor = super.visitMethod(access, name, descriptor, signature, exceptions);
+            if (visitor == null) {
+                return null;
+            }
+
+            return new LocalVariablesSorter(Gizmo.ASM_API_VERSION, access, descriptor, visitor) {
+                @Override
+                public void visitCode() {
+                    if ("<clinit>".equals(name)) {
+                        super.visitLdcInsn(className);
+                        super.visitMethodInsn(Opcodes.INVOKESTATIC, JBOSS_LOGGER_BINARY_NAME, "getLogger",
+                                GET_LOGGER_DESCRIPTOR, false);
+                        super.visitFieldInsn(Opcodes.PUTSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
+                                JBOSS_LOGGER_DESCRIPTOR);
+                        generatedLoggerFieldInitialization = true;
+                    }
+
+                    super.visitCode();
+                }
+
+                @Override
+                public void visitMethodInsn(int opcode, String owner, String name, String descriptor, boolean isInterface) {
+                    if (!QUARKUS_LOG_BINARY_NAME.equals(owner)) {
+                        super.visitMethodInsn(opcode, owner, name, descriptor, isInterface);
+                        return;
+                    }
+
+                    Type[] argTypes = Type.getArgumentTypes(descriptor);
+                    int numArgs = argTypes.length;
+                    int[] locals = null;
+
+                    boolean directStackManipulation = isDirectStackManipulationPossible(argTypes);
+
+                    // for 0, 1 or 2 arguments of the logger method, where each only takes 1 stack slot,
+                    // direct stack manipulation is possible
+                    // for 3 or more arguments, or less arguments but at least one taking 2 stack slots,
+                    // we move them from stack to local variables and restore later
+                    if (!directStackManipulation) {
+                        // stack: [arg1 arg2 arg3 arg4] locals: {}
+                        // stack: [arg1 arg2 arg3]      locals: {l1 = arg4}
+                        // stack: [arg1 arg2]           locals: {l1 = arg4 l2 = arg3}
+                        // stack: [arg1]                locals: {l1 = arg4 l2 = arg3 l3 = arg2}
+                        // stack: []                    locals: {l1 = arg4 l2 = arg3 l3 = arg2 l4 = arg1}
+                        locals = new int[numArgs];
+                        for (int i = numArgs - 1; i >= 0; i--) {
+                            locals[i] = newLocal(argTypes[i]);
+                            super.visitVarInsn(argTypes[i].getOpcode(Opcodes.ISTORE), locals[i]);
+                        }
+                    }
+
+                    // stack: [] -> [logger]
+                    super.visitFieldInsn(Opcodes.GETSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
+                            JBOSS_LOGGER_DESCRIPTOR);
+
+                    if (directStackManipulation) {
+                        if (numArgs == 1) {
+                            // stack: [arg1 logger] -> [logger arg1]
+                            super.visitInsn(Opcodes.SWAP);
+                        } else if (numArgs == 2) {
+                            // stack: [arg1 arg2 logger] -> [logger arg1 arg2 logger]
+                            super.visitInsn(Opcodes.DUP_X2);
+                            // stack: [logger arg1 arg2 logger] -> [logger arg1 arg2]
+                            super.visitInsn(Opcodes.POP);
+                        }
+                    } else {
+                        // stack: [logger]                     locals: {l1 = arg4 l2 = arg3 l3 = arg2 l4 = arg1}
+                        // stack: [logger arg1]                locals: {l1 = arg4 l2 = arg3 l3 = arg2}
+                        // stack: [logger arg1 arg2]           locals: {l1 = arg4 l2 = arg3}
+                        // stack: [logger arg1 arg2 arg3]      locals: {l1 = arg4}
+                        // stack: [logger arg1 arg2 arg3 arg4] locals: {}
+                        for (int i = 0; i < numArgs; i++) {
+                            super.visitVarInsn(argTypes[i].getOpcode(Opcodes.ILOAD), locals[i]);
+                        }
+                    }
+
+                    super.visitMethodInsn(Opcodes.INVOKEVIRTUAL, JBOSS_LOGGER_BINARY_NAME, name, descriptor, false);
+                }
+
+                private boolean isDirectStackManipulationPossible(Type[] argTypes) {
+                    return argTypes.length == 0
+                            || argTypes.length == 1 && argTypes[0].getSize() == 1
+                            || argTypes.length == 2 && argTypes[0].getSize() == 1 && argTypes[1].getSize() == 1;
+                }
+            };
+        }
+
+        @Override
+        public void visitEnd() {
+            if (!generatedLoggerField) {
+                generateLoggerField();
+            }
+
+            if (!generatedLoggerFieldInitialization) {
+                MethodVisitor visitor = super.visitMethod(Opcodes.ACC_STATIC, "<clinit>", "()V", null, null);
+                visitor.visitCode();
+                visitor.visitLdcInsn(className);
+                visitor.visitMethodInsn(Opcodes.INVOKESTATIC, JBOSS_LOGGER_BINARY_NAME, "getLogger",
+                        GET_LOGGER_DESCRIPTOR, false);
+                visitor.visitFieldInsn(Opcodes.PUTSTATIC, classNameBinary, SYNTHETIC_LOGGER_FIELD_NAME,
+                        JBOSS_LOGGER_DESCRIPTOR);
+                visitor.visitInsn(Opcodes.RETURN);
+                visitor.visitMaxs(1, 0);
+                visitor.visitEnd();
+
+                generatedLoggerFieldInitialization = true;
+            }
+
+            super.visitEnd();
+        }
+
+        private void generateLoggerField() {
+            super.visitField(Opcodes.ACC_PRIVATE | Opcodes.ACC_STATIC | Opcodes.ACC_FINAL,
+                    SYNTHETIC_LOGGER_FIELD_NAME, JBOSS_LOGGER_DESCRIPTOR, null, null);
+            generatedLoggerField = true;
+        }
+    }
+}

core/deployment/src/main/java/io/quarkus/deployment/steps/ClassTransformingBuildStep.java

@@ -78,6 +78,7 @@ TransformedClassesBuildItem handleClassTransformation(List<BytecodeTransformerBu
         Map<String, Set<String>> constScanning = new HashMap<>();
         Set<String> eager = new HashSet<>();
         Set<String> nonCacheable = new HashSet<>();
+        Map<String, Integer> classReaderOptions = new HashMap<>();
         for (BytecodeTransformerBuildItem i : bytecodeTransformerBuildItems) {
             bytecodeTransformers.computeIfAbsent(i.getClassToTransform(), (h) -> new ArrayList<>())
                     .add(i);
@@ -93,6 +94,7 @@ TransformedClassesBuildItem handleClassTransformation(List<BytecodeTransformerBu
             if (!i.isCacheable()) {
                 nonCacheable.add(i.getClassToTransform());
             }
+            classReaderOptions.put(i.getClassToTransform(), i.getClassReaderOptions());
         }
         QuarkusClassLoader cl = (QuarkusClassLoader) Thread.currentThread().getContextClassLoader();
         Map<String, Path> transformedToArchive = new ConcurrentHashMap<>();
@@ -132,7 +134,8 @@ public byte[] apply(String className, byte[] originalBytes) {
                                 return originalBytes;
                             }
                         }
-                        byte[] data = transformClass(className, visitors, classData, preVisitFunctions);
+                        byte[] data = transformClass(className, visitors, classData, preVisitFunctions,
+                                classReaderOptions.getOrDefault(className, 0));
                         TransformedClassesBuildItem.TransformedClass transformedClass = new TransformedClassesBuildItem.TransformedClass(
                                 className, data,
                                 classFileName, eager.contains(className));
@@ -190,7 +193,8 @@ public TransformedClassesBuildItem.TransformedClass call() throws Exception {
                                         return null;
                                     }
                                 }
-                                byte[] data = transformClass(className, visitors, classData, preVisitFunctions);
+                                byte[] data = transformClass(className, visitors, classData, preVisitFunctions,
+                                        classReaderOptions.getOrDefault(className, 0));
                                 TransformedClassesBuildItem.TransformedClass transformedClass = new TransformedClassesBuildItem.TransformedClass(
                                         className, data,
                                         classFileName, eager.contains(className));
@@ -256,7 +260,7 @@ private void handleRemovedResources(ClassLoadingConfig classLoadingConfig, Curat
     }
 
     private byte[] transformClass(String className, List<BiFunction<String, ClassVisitor, ClassVisitor>> visitors,
-            byte[] classData, List<BiFunction<String, byte[], byte[]>> preVisitFunctions) {
+            byte[] classData, List<BiFunction<String, byte[], byte[]>> preVisitFunctions, int classReaderOptions) {
         for (BiFunction<String, byte[], byte[]> i : preVisitFunctions) {
             classData = i.apply(className, classData);
             if (classData == null) {
@@ -272,7 +276,7 @@ private byte[] transformClass(String className, List<BiFunction<String, ClassVis
             for (BiFunction<String, ClassVisitor, ClassVisitor> i : visitors) {
                 visitor = i.apply(className, visitor);
             }
-            cr.accept(visitor, 0);
+            cr.accept(visitor, classReaderOptions);
             data = writer.toByteArray();
         } else {
             data = classData;