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?

How about printing the entire stack trace (not just the 3rd element's method name), and seeing what the difference is? — Andy Turner, Jun 20 '16 at 23:46
I suspect that [this answer](http://stackoverflow.com/a/1069150/3788176) and its comments will help you. — Andy Turner, Jun 20 '16 at 23:50
[This answer](http://stackoverflow.com/questions/442747/getting-the-name-of-the-current-executing-method/8592871#8592871) might also be able to help. Apparently it's not even consistent between different versions of Oracle's JVM, so I wouldn't expect it to be reliable on a completely different JVM. — Marvin, Jun 23 '16 at 21:20

score 5 · Answer 1 · edited Nov 23 '21 at 06:50

5

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 ?)

edited Nov 23 '21 at 06:50

Glorfindel

21,988
13
81
109

answered Jun 21 '16 at 05:04

juherr

5,640
1
21
63

I am already doing that for logging the name of a test method, but in above, we are talking about non-test methods. – Greg Jun 21 '16 at 12:45
1

I think you should explain your need more: why do you want to do that? Did you considere to use aspect for that? – juherr Jun 23 '16 at 09:35
it's to assist with troubleshooting while looking through the log file. our log files are pretty big, and we have lots of methods, knowing where we were last, or what method is printing what statements, oftentimes helps us. sorry, not familiar with aspect, but can look into it. – Greg Jun 23 '16 at 13:58
aspect is just a way to inject some code before/after/around methods and provides you the meta data of the method (like its name). But I've no idea how it will be complicate to use it in test context. Another solution could be using Spock framework which provides built-in feature like the one you want. But again, it may take too many time depending on your work context. – juherr Jun 23 '16 at 15:17

score 5 · Accepted Answer · edited May 23 '17 at 12:14

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.

score 3 · Answer 3 · edited May 23 '17 at 11:51

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:

Steffen Harbich · Answer 4 · 2016-06-23T12:55:41.233

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

score 1 · Answer 5 · answered Jun 29 '16 at 18:16

1

I think its the specific depth that is causing the issue which is 2 in your scenario.

So, instead of writing

String method = Thread.currentThread().getStackTrace()[2].getMethodName();

if you write

StackTraceElement[] ste = Thread.currentThread().getStackTrace();
String method = null;
boolean doNext = false;
for (StackTraceElement s : ste) {
       if (doNext) {
          method = s.getMethodName();
          return;
       }
       doNext = s.getMethodName().equals("getStackTrace");
   }

It will work only for JDK 1.5+

The other option is as below:

String method = new Object(){}.getClass().getEnclosingMethod().getName();

Or a slower option will be :

String method = new Exception().getStackTrace()[0].getMethodName();

As this will create an instance of Exception everytime.

Hope that helps you out.

answered Jun 29 '16 at 18:16

Aman Chhabra

3,824
1
23
39

What's the evidence for `new Object(){}.getClass().getEnclosingMethod().getName()` being faster than `new Exception().getStackTrace()[0].getMethodName()`? – Steffen Harbich Jul 01 '16 at 06:09
1

@SteffenHarbich With first option it will only need to create an Object instance whereas for the second option it will need to create three instance: Exception, Throwable and Object . To prove, I wrote a program to fetch and print name 1000000 times and here we go... the out come is : 1) for new Object(){}.getClass().getEnclosingMethod().getName() Total time taken is 7 seconds, 701 milliseconds 476129 nanoseconds whereas for 2) for new Exception().getStackTrace()[0].getMethodName() Total time taken is 12 seconds, 222 milliseconds 112528 nanoseconds – Aman Chhabra Jul 01 '16 at 14:31

score 0 · Answer 6 · answered Jun 23 '16 at 07:42

Log4J finds the method name by searching down the stack trace until it finds the target class name which must be passed in, then reads the method name.

In your code, you could use a similar technique - instead of a static method Utils you could create an instance in your test, passing in the class of the test:

Utils utils = new Utils(MyTest.class);

Then use the previously mentioned search technique in the Utils.logTitle() method.

Utils.logTitle() would search forwards through stack trace elements of a newly created Throwable until it finds the first element with the desired target class.

Remko Popma · Answer 7 · 2016-06-30T12:07:07.177

Log4j 2 uses the fully qualified class name of the Logger to locate the class and method from which the Logger was called. The code to find the location follows below. Feel free to use it.

Note that the loop starts from the bottom of the stacktrace; this is necessary to detect exceptional cases where the logger is called recursively (perhaps from the toString() method of an object that was logged). In such cases we want to report the first class/method that called the Logger, not the last one, so we have no choice but to walk the stack trace from the bottom up.

public static StackTraceElement calcLocation(final String fqcnOfLogger) {
    if (fqcnOfLogger == null) {
        return null;
    }
    // LOG4J2-1029 new Throwable().getStackTrace is faster 
    // than Thread.currentThread().getStackTrace().
    final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    StackTraceElement last = null;
    for (int i = stackTrace.length - 1; i > 0; i--) {
        final String className = stackTrace[i].getClassName();
        if (fqcnOfLogger.equals(className)) {
            return last;
        }
        last = stackTrace[i];
    }
    return null;
}

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

7 Answers7