Log Method Calls in Java System Classes

Question

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());
    }
}

Answer 1

If this is for the purpose of learning or analysis, why don't you just use a debugger? I am going to show you an example in IntelliJ IDEA:

Given this code somewhere in your main method or test:

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

When defining a method breakpoint in the debugger like this:

And defining its properties like this (breakpoint does not suspend running program but logs method entry, other filter criteria and log information is also possible):

Then you will get a console log like this (shortened because it is quite long):

Connected to the target VM, address: '127.0.0.1:54734', transport: 'socket'
Method 'java.nio.ByteBuffer.allocate()' entered at java.nio.ByteBuffer.allocate(ByteBuffer.java:333)
Method 'java.nio.ByteBuffer.<init>()' entered at java.nio.ByteBuffer.<init>(ByteBuffer.java:281)
Method 'java.nio.ByteBuffer.hasArray()' entered at java.nio.ByteBuffer.hasArray(ByteBuffer.java:970)
Method 'java.nio.ByteBuffer.array()' entered at java.nio.ByteBuffer.array(ByteBuffer.java:993)
Method 'java.nio.ByteBuffer.arrayOffset()' entered at java.nio.ByteBuffer.arrayOffset(ByteBuffer.java:1021)
(...)
Method 'java.nio.ByteBuffer.wrap()' entered at java.nio.ByteBuffer.wrap(ByteBuffer.java:396)
Method 'java.nio.ByteBuffer.wrap()' entered at java.nio.ByteBuffer.wrap(ByteBuffer.java:373)
Method 'java.nio.ByteBuffer.<init>()' entered at java.nio.ByteBuffer.<init>(ByteBuffer.java:281)
Method 'java.nio.ByteBuffer.array()' entered at java.nio.ByteBuffer.array(ByteBuffer.java:993)
Method 'java.nio.ByteBuffer.toString()' entered at java.nio.ByteBuffer.toString(ByteBuffer.java:1085)
08:23:16.943 [main] INFO  d.s.s.q.TestFakeByteBufferAdvice - Real........: java.nio.HeapByteBuffer[pos=0 lim=3 cap=3] [97, 98, 99]
Method 'java.nio.ByteBuffer.hasArray()' entered at java.nio.ByteBuffer.hasArray(ByteBuffer.java:970)
Method 'java.nio.ByteBuffer.array()' entered at java.nio.ByteBuffer.array(ByteBuffer.java:993)
(...)
Method 'java.nio.ByteBuffer.arrayOffset()' entered at java.nio.ByteBuffer.arrayOffset(ByteBuffer.java:1021)
Method 'java.nio.ByteBuffer.array()' entered at java.nio.ByteBuffer.array(ByteBuffer.java:993)
Method 'java.nio.ByteBuffer.arrayOffset()' entered at java.nio.ByteBuffer.arrayOffset(ByteBuffer.java:1021)
Disconnected from the target VM, address: '127.0.0.1:54734', transport: 'socket'

Process finished with exit code 0

Play around with the breakpoint options and find a setting which helps you the most. You could for example filter out certain methods of no interest or specify other conditions, evaluate expressions and log them or whatever you dream up.

---

Update 2020-05-17: It took a few weeks for JetBrains to react, but they agreed to improve the documentation and also to fix one bug:

• https://youtrack.jetbrains.com/issue/DOC-9130
• https://youtrack.jetbrains.com/issue/IDEA-240671

Answer 2

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());
    }
}