Search code examples
javaaopaspectjpowermockjmockit

Log Method Calls in Java System Classes


I'm looking for a way to log calls to all methods in java.nio.ByteBuffer.

I just want to know which methods are being called.

This was possible with JMockit, but as of version 1.47 some infinitely wise individual decided to remove support of private methods & version 1.46 doesn't work too well with JDK 9 and later.

Can anyone suggest a tool? It doesn't necessarily need to be a Unit-Test framework, but it should work in Eclipse.

I need at least support for JDK 11 (preferably JDK 13)

Just for the record, here's the code that works with JMockit 1.46 & JDK 1.8:

import java.nio.ByteBuffer;
import org.junit.Test;
import org.slf4j.*;
import mockit.*;

public class TestFakeByteBufferAdvice {

    private static final Logger LOG = LoggerFactory.getLogger(TestFakeByteBufferAdvice.class);

    public static final class FakeByteBuffer extends MockUp<ByteBuffer> {
        @Mock
        public Object $advice(Invocation invocation) {
            LOG.info("$advice.....: {} {}", invocation.getInvokedMember(), invocation);

            return invocation.proceed();
        }
    }

    @Test
    public void getFakeByteBuffer() {

        final ByteBuffer real  = ByteBuffer.wrap("abc".getBytes());
        LOG.info("Real........: {} {}", real, real.array());

        LOG.info("MockUp......: {}",    new FakeByteBuffer());

        final ByteBuffer fake  = ByteBuffer.wrap("def".getBytes());
        LOG.info("Fake........: {} {}", fake, fake.array());
    }
}

Solution

  • Well, I managed to hack my way to a solution.

    Firstly, JMockit doesn't work very well with JDK13, so I backported the JDK13 Http Client to JDK8. Its an evil hack, but sufficient for my test-case.

    Then I used a slightly older Version (1.46) of JMockit because some comedian decided that no one should be allowed to Fake classes with private methods.

    Then I stored the objects I wanted to trace in a List, which makes it possible to exclude unwanted Objects from Logging via an identity (==) comparison.

    Still JMockit may crash on some methods (in the example below, I've commented them out), so it's an idea to suppress the logging after the Exception.
    I've reported this to the JMockit people: https://github.com/jmockit/jmockit1/issues/667

    Similarly, it makes sense to suppress the logging while constructing the test-case to keep the Output quantities down. I used an AtomicBoolean for that.

    Still the trace didn't solve it completely, but throwing in a Stacktrace led me to the solution: the following Call-chain was reading my ByteBuffers:
    sun.nio.ch.write(ByteBuffer[] srcs, int offset, int length)
    sun.nio.ch.write(FileDescriptor fd, ByteBuffer src, long position, NativeDispatcher nd)
    java.nio.DirectByteBuffer.put(ByteBuffer src)

    The DirectByteBuffer was using some clever tricks to read out my ByteBuffer.

    The solution only works with my Http Client hack, but here it is anyway, just for the record. Maybe some of it will help others debugging some other classes:

    package http.jmockit;
    
    import java.net.*;
    import java.net.http.*;
    import java.net.http.HttpRequest.BodyPublisher;
    import java.nio.ByteBuffer;
    import java.util.*;
    import java.util.concurrent.atomic.AtomicBoolean;
    import org.slf4j.*;
    import mockit.*;
    
    public class TestHttpIdentity {
    
        private static final Logger        LOG         = LoggerFactory.getLogger(TestHttpIdentity.class);
        private static final AtomicBoolean LOG_ENABLED = new AtomicBoolean();
        private static final List<Object>  TRACKED     = new ArrayList<>();
    
        public static final class FakeByteBuffer extends MockUp<ByteBuffer> {
            @Mock
            public Object $advice(final Invocation invocation) {
    
                if (TRACKED.stream().noneMatch(tracked -> tracked == invocation.getInvokedInstance())) {
                    return invocation.proceed();
                }
    
                if (LOG_ENABLED.get()) {
                    LOG    .info("$advice.invokedInstance.: {}", invocation.getInvokedInstance(), "" /* (makes signature unique)*/);
                    LOG    .info("$advice.invokedMember...: {}", invocation.getInvokedMember(),   "" /* (makes signature unique)*/);
    //              Thread.dumpStack(); // Use Stack Trace as last measure if needs be
                }
    
                Object     result = "Not available due to Exception in invocation.proceed()";
                try {
                    /**/   result = invocation.proceed();
                    return result;
                }
                catch (final Throwable e) {
    
                    for (final Object arg : invocation.getInvokedArguments()) {
                        LOG.info("$advice.arg.............: {} class={}", arg,   arg == null ? "?" : arg.getClass());
                    }
                    LOG    .info("$advice.Result..........: {}", result);
    
                    LOG_ENABLED.set(false);  // Disable Logging when JMockit fails
    
                    try {Thread.sleep(100);} catch (final InterruptedException shortDelayToSyncLoggingOutput) {}
    
                    e.printStackTrace();
                    throw e;
                }
            }
        }
    
        public static void main(final String[] args) throws Exception {
    
            LOG.info("MockUp..................: {}", new FakeByteBuffer());
    
            final ByteBuffer[] byteBuffers  = TestBytes.asWrappedByteBuffers();
    
            for (final ByteBuffer byteBuffer : byteBuffers) {
                LOG.info("byteBuffer..............: {}", byteBuffer);
    
                final int limit    = byteBuffer.limit();
                final int position = byteBuffer.position();
    
                TRACKED.add(byteBuffer);  // Track Objects via their Identity (==)
    
                LOG.info("Test Bytes..............: {}", byteBuffers, "");
                LOG.info("byteBuffer0.array().....: {}", byteBuffer.array());
                LOG.info("byteBuffer0.capacity()..: {}", byteBuffer.capacity());
                LOG.info("byteBuffer0.get().......: {}", byteBuffer.get());
    //          LOG.info("byteBuffer0.get(byte[]).: {}", byteBuffers0.get(new byte[5]));  // ClassCastException
                LOG.info("byteBuffer0.get(byte[]->) {}", byteBuffer.get(new byte[5], 0, 5));
                LOG.info("byteBuffer0.get(0)......: {}", byteBuffer.get(0));
                LOG.info("byteBuffer0.hasArray()..: {}", byteBuffer.hasArray());
                LOG.info("byteBuffer0.hasRemaining: {}", byteBuffer.hasRemaining());
                LOG.info("byteBuffer0.isDirect()..: {}", byteBuffer.isDirect());
                LOG.info("byteBuffer0.isReadOnly(): {}", byteBuffer.isReadOnly());
                LOG.info("byteBuffer0.limit().....: {}", limit);
                LOG.info("byteBuffer0.limit(0)....: {}", byteBuffer.limit(limit));
                LOG.info("byteBuffer0.mark(0).....: {}", byteBuffer.mark());
                LOG.info("byteBuffer0.order().....: {}", byteBuffer.order());
                LOG.info("byteBuffer0.position()..: {}", position);
                LOG.info("byteBuffer0.position(99): {}", byteBuffer.position(99));
                LOG.info("byteBuffer0.remaining().: {}", byteBuffer.remaining());
    //          LOG.info("byteBuffer0.reset().....: {}", byteBuffers0.reset());      // -> InvalidMarkException
                LOG.info("byteBuffer0.rewind()....: {}", byteBuffer.rewind());
                LOG.info("byteBuffer0.slice().....: {}", byteBuffer.slice());
    
                byteBuffer.rewind();
                byteBuffer.position(position);
                byteBuffer.limit   (limit);
    
                LOG.info("byteBuffer..............: {}", byteBuffer);
            }
            final BodyPublisher pub = new ByteArrayBodyPublisherIterator(byteBuffers);
    
            LOG_ENABLED.set(false);  // Enable Logging now we've got things set up.
    
            final HttpRequest request = HttpRequest.newBuilder()
                    .uri(new URI("http://localhost:631"))
                    .headers("Content-Type", "application/ipp")
                    .POST(pub)
                    .build();
    
            HttpResponse<byte[]> response = HttpClient
                    .newBuilder()
                    .build()
                    .send(request, HttpResponse.BodyHandlers.ofByteArray());
    
            LOG.info("Result......: {} {}", response, response.body());
        }
    }