method intercepting not working as expected

[WestFarmer]

my goal: intercept jdbc connection pool connection creation and closing event.

my java gent :

AgentBuilder.Transformer constructorTransformer = new AgentBuilder.Transformer() {
            @Override
            public DynamicType.Builder<?> transform(DynamicType.Builder<?> builder, TypeDescription typeDescription,
                    ClassLoader classLoader, JavaModule javaModule) {
                return builder.visit(Advice.to(ConnectInterceptor.class).on(isConstructor()));
            }
        };

        AgentBuilder.Transformer methodsTransformer = new AgentBuilder.Transformer() {
            @Override
            public DynamicType.Builder<?> transform(DynamicType.Builder<?> builder, TypeDescription typeDescription,
                    ClassLoader classLoader, JavaModule javaModule) {
                return builder.method(namedOneOf("close", "unwrap", "isWrapperFor", "createStatement", "prepareStatement", "prepareCall", "nativeSQL",
                        "setAutoCommit", "getAutoCommit", "commit", "rollback", "close", "isClosed", "getMetaData",
                        "setReadOnly", "isReadOnly", "setCatalog", "getCatalog", "setTransactionIsolation",
                        "getTransactionIsolation", "getWarnings", "clearWarnings", "createStatement",
                        "prepareStatement", "prepareCall", "getTypeMap", "setTypeMap", "setHoldability",
                        "getHoldability", "setSavepoint", "setSavepoint", "rollback", "releaseSavepoint",
                        "createStatement", "prepareStatement", "prepareCall", "prepareStatement", "prepareStatement",
                        "prepareStatement", "createClob", "createBlob", "createNClob", "createSQLXML", "isValid",
                        "setClientInfo", "setClientInfo", "getClientInfo", "getClientInfo", "createArrayOf",
                        "createStruct", "setSchema", "getSchema", "abort", "setNetworkTimeout", "getNetworkTimeout").and(not(isAbstract())))
                        .intercept(MethodDelegation.to(ConnectInterceptor.class));
            }
        };

        AgentBuilder.Listener listener = new AgentBuilder.Listener.WithErrorsOnly(
                new AgentBuilder.Listener.StreamWriting(System.out));

        new AgentBuilder.Default().type(named("org.apache.commons.dbcp.DelegatingConnection")).transform(constructorTransformer).transform(methodsTransformer)
                .with(listener).installOn(inst);

my interceptor:

package org.wxt.xtools.agents;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.lang.reflect.Constructor;
import java.lang.reflect.Method;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.concurrent.Callable;
import org.wxt.xtools.agents.utils.StringUtils;

import ch.qos.logback.classic.Logger;
import net.bytebuddy.asm.Advice;
import net.bytebuddy.asm.Advice.This;
import net.bytebuddy.implementation.bind.annotation.Origin;
import net.bytebuddy.implementation.bind.annotation.RuntimeType;
import net.bytebuddy.implementation.bind.annotation.SuperCall;

/**
 * 
 * @author ggfan
 *
 */
public class ConnectInterceptor {

    // fields below must be public, as we will access them from the intercepting methods 
    public static Map<Integer, ConnectionCreationInfo> conns = new HashMap<Integer, ConnectionCreationInfo>();

    public static Map<String, Integer> counstsByStack = new HashMap<String, Integer>();

    public static Logger log = JDBCLeakDetector.log;

    public static List<ConnectionCreationInfo> getInfo(){
        List<ConnectionCreationInfo> data = new ArrayList<ConnectionCreationInfo>();
        for(ConnectionCreationInfo ci : conns.values()) {
            ConnectionCreationInfo copy = new ConnectionCreationInfo();
            copy.setHash(ci.getHash());
            copy.setStackHash(ci.getStackHash() + "(" + counstsByStack.get(ci.getStackHash()) + ")");
            copy.setCreationTime(ci.getCreationTime());
            copy.setLastActiveTime(ci.getLastActiveTime());
            data.add(copy);
        }
        return data;
    }

    public static String getStack(String shash) {
        for(ConnectionCreationInfo ci : conns.values()) {
            if(ci.getStackHash().equals(shash)) {
                return ci.getStack();
            }
        }
        return null;
    }

    @RuntimeType
    public static Object interceptor(@Origin Class<?> clazz, @Origin Method method, @SuperCall Callable<?> callable,
            @net.bytebuddy.implementation.bind.annotation.This Object inst) throws Exception {
        int hashCode = System.identityHashCode(inst);
        ConnectionCreationInfo ci = conns.get(hashCode);
        if(ci == null) {
            log.error("Connection@{} is not recorded", hashCode);
        }
        if (method.getName().equals("close")) {
            log.info("Connnection@{} released", hashCode);

            String stackHash = ci.getStackHash();
            Integer scount = counstsByStack.get(stackHash);
            if(scount != null && scount > 0) {
                int newscount = scount - 1;
                log.debug("set connection count to {} by stack hash {}", newscount, stackHash);
                if(newscount == 0) {
                    counstsByStack.remove(stackHash);
                }else {
                    counstsByStack.put(stackHash, newscount);
                }
            }else {
                log.error("Connection count by stack hash {} is not supposed to be null or less than zero", stackHash);
            }

            conns.remove(hashCode);
        } else {
            log.debug("Connnection@{} used by {}", hashCode, method.getName());
            ci.setLastActiveTime(System.currentTimeMillis());
        }
        return callable.call();
    }

    @Advice.OnMethodExit
    public static void intercept(@net.bytebuddy.asm.Advice.Origin Constructor<?> m, @This Object inst)
            throws Exception {
        // some CP library override hashCode method
        int hashCode = System.identityHashCode(inst);
        ConnectionCreationInfo ci = new ConnectionCreationInfo();
        ci.setHash(hashCode);
        ci.setCreationTime(System.currentTimeMillis());
        StringWriter sw = new StringWriter();
        Throwable t = new Throwable("");
        t.printStackTrace(new PrintWriter(sw));
        String stackTrace = sw.toString();
        sw.close();
        ci.setStack(stackTrace);
        String shash = StringUtils.md5(stackTrace);
        ci.setStackHash(shash);
        log.info("Connnection@{} acquired by {}", hashCode, shash);
        log.debug("Connection creation call stack: ", t);
        conns.put(hashCode, ci);
        Integer scount = counstsByStack.get(ci.getStackHash());
        if(scount == null) {
            counstsByStack.put(ci.getStackHash(), 1);
        }else {
            counstsByStack.put(ci.getStackHash(), scount + 1);
        }
    }

}

but when testing with dpcp 1.4 on tomcat, I can only get two times close method intercepted, but according to applciation log where is much more connection closing event, I see a lot logs like below

2021-09-15 15:48:57,336 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Releasing JDBC Connection [jdbc:oracle:thin:@172.31.124.43:1521/pas, UserName=PAS, Oracle JDBC driver] after transaction
2021-09-15 15:48:57,336 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource

what's wrong with my code? need some suggestion.

[raphw]

Maybe the method is overridden in a subclass? Instead of named, try wrapping this with hasSuperType. Also, add a listener to see if some instrumentation is failing.

[WestFarmer]

@raphw you are right , I shoud intercept on org.apache.common.dbcp.PoolableConnection, which is subclass of org.apache.common.dbcp.DelegatingConnection, it overide 'close' mthod...

I finally got everything works, my agent helped a legacy project find a stupid jdbc connection leak problem.

thanks for you creating this great tool bytebuddy.

[WestFarmer]

@raphw in my intercepting method, is callable.call(); means call the original method ?

[raphw]

Yes.