Getting different results for getStackTrace()[2].getMethodName()

Question

For logging purposes, I created a method logTitle() that prints out the calling method name for our TestNG tests. Sample code is below.

@Test
public void test1() throws Exception {
    method1();
}

public static void method1() throws Exception {
    Utils.logTitle(2);
}

...

public static void logTitle(Integer level) throws Exception {

    // Gets calling method name
    String method = Thread.currentThread().getStackTrace()[2].getMethodName();
    // This would get current method name
    switch (level) {
    case 1:
        logger.info("=======================================================");
        logger.info(method);
        logger.info("=======================================================");
        break;
    case 2:
        logger.info("------------------------------------");
        logger.info(method);
        logger.info("------------------------------------");
        break;
    case 3:
        logger.info("---------------------");
        logger.info(method);
        logger.info("---------------------");
        break;
    case 4:
        logger.info("--------- " + method + " ------------");
        break;
    default:
        logger.info(method);
    }
}

The problem is I am getting different results for logTitle() on two different machines.

Everyone's laptop returns correctly:

2016-06-20 14:22:06 INFO  - ------------------------------------
2016-06-20 14:22:06 INFO  - method1
2016-06-20 14:22:06 INFO  - ------------------------------------

Our dev unix box returns differently:

2016-06-20 14:42:26 INFO  - ------------------------------------
2016-06-20 14:42:26 INFO  - logTitle
2016-06-20 14:42:26 INFO  - ------------------------------------

This works correctly on everyone else's laptop, just not the dev unix box. I think the dev unix box is using IBM's version of Java, while everyone else is using Oracle's version of Java, but not sure if that is the culprit or not.

Any ideas?

Answer 1

From Javadoc:

Some virtual machines may, under some circumstances, omit one or more stack frames from the stack trace. In the extreme case, a virtual machine that has no stack trace information concerning this throwable is permitted to return a zero-length array from this method.

So, the only guaranteed way to do this is to use aspects, or collect stack trace with some other custom way. But you can combine this approach with fallback to some way of getting current method's name (for case when your logTitle method will be inlined). It can be found here, for example. Again, no guarantee, but better chance.

Answer 2

The simpler way to have a test method name is by using a @BeforeMethod and injecting the Method. See TestNG's documentation, here.

Just store the name somewhere and use it in your log (why not in a @AfterMethod ?)

Answer 3

My guess, and as mentioned by MeBigFatGuy. This can happen because of the different in implementation/defaults of the JIT compiler of the IBM/Oracle JVM when doing method inlining optimization.

I suggest running the code in the dev unix box with

-Xjit:disableInlining  

and see if the issue disappear.

If this will work for you it may be fine for testing, but as mentioned in Alexey Adamovskiy answer we cannot trust java to be consist in the stack frames.

See also:

• Would Java inline method(s) during optimization?
• Selectively disabling the JIT compiler
• Java method inlining performance considerations

Answer 4

I guess the behavior is JVM specific. In the past I came up with this solution:

// find first stack trace entry that is not in this class
Optional<StackTraceElement> ste = Iterables.tryFind(
        Arrays.asList(new RuntimeException().getStackTrace()), 
        new Predicate<StackTraceElement>() {
            @Override
            public boolean apply(StackTraceElement input) {
                return !input.getClassName().equals(PutYourClassHere.class.getName());
            }
        });

if (ste.isPresent()) {
    LOG.trace("Method called by: {}.{}", ste.get().getClassName(), ste.get().getMethodName());
}

The snippet is using Google Guava because this is for Java 7. If you have Java 8, you can use Streams API and lambdas. I made the ste.isPresent() check because I encountered an empty stack trace once. As far as I remember the Oracle JVM is skipping stack traces when the same exception is thrown over and over again.

EDIT: Java 8 way

Optional<StackTraceElement> ste = Arrays.stream(new RuntimeException().getStackTrace())
            .filter(x -> !x.getClassName().equals(Utils.class.getName()))
            .findFirst();