Where did my logs get these extra StackTraceElements that point to line of classname?

Viewed 38

I have a stacktrace that from my logs that looks like:

Aug 10, 2022 10:10:10 PM io.grpc.internal.SerializingExecutor run
SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable@5703a7b7
java.lang.NullPointerException
    at MyProtoFile$MyProtoClass.<init>(MyProtoFile.java:20)
    at MyProtoFile$MyProtoClass.<init>(MyProtoFile.java:10)
    at MyProtoFile$MyProtoClass$1.parsePartialFrom(MyProtoFile.java:50)
    at MyProtoFile$MyProtoClass$1.parsePartialFrom(MyProtoFile.java:40)
    at com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:86)
    at com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:48)
    at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parseFrom(ProtoLiteUtils.java:223)
    at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parse(ProtoLiteUtils.java:215)
    at io.grpc.protobuf.lite.ProtoLiteUtils$MessageMarshaller.parse(ProtoLiteUtils.java:118)
    at io.grpc.MethodDescriptor.parseRequest(MethodDescriptor.java:307)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailableInternal(ServerCallImpl.java:318)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.messagesAvailable(ServerCallImpl.java:301)
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1MessagesAvailable.runInContext(ServerImpl.java:834)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.base/java.lang.Thread.run(Unknown Source)

However, when you look at the corresponding generated code, MyProtoFile$MyProtoClass.<init>(MyProtoFile.java:10), MyProtoFile$MyProtoClass$1.parsePartialFrom(MyProtoFile.java:40), and com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:48) point to the line that begins that class definition with public [static] class ClassName, for the first time the stacktrace enters that class.

I am not able to provide the source code generated by protobuf for MyProtoFile, but the rest of the stack trace is publicly available on github. For example, Abstract parser is available here: https://github.com/protocolbuffers/protobuf/blob/v3.20.0/java/core/src/main/java/com/google/protobuf/AbstractParser.java. You can see that line 48 is the beginning of the class definition for AbstractParser.

If you try running with Vanilla java 11:

public class ConstructorStackTrace {

    public static class InnerClass {
        public InnerClass() {
            throw new NullPointerException("hello");
        }
    }

    public static void main(String []args){
        System.err.println("OneConstructor");
        try {
            OneConstructor constructorStackTrace = new OneConstructor();
        } catch (Exception e) {
            e.printStackTrace();
        }
        System.err.println("NestedConstructor");
        try {
            NestedConstructor constructorStackTrace = new NestedConstructor();
        } catch (Exception e) {
            e.printStackTrace();
        }
        System.err.println("InnerClass");
        try {
            InnerClass constructorStackTrace = new InnerClass();
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

class OneConstructor {
    public  OneConstructor() {
        throw new NullPointerException("hello");
    }
}

class NestedConstructor {
    public NestedConstructor() {
        this("Hello");
    }

    public NestedConstructor(String hello) {
        throw new NullPointerException("hello");
    }
}

You get the below which do not have StackTraceElements for the first line of the class definition:

OneConstructor
java.lang.NullPointerException: hello
        at OneConstructor.<init>(ConstructorStackTrace.java:33)
        at ConstructorStackTrace.main(ConstructorStackTrace.java:12)
NestedConstructor
java.lang.NullPointerException: hello
        at NestedConstructor.<init>(ConstructorStackTrace.java:43)
        at NestedConstructor.<init>(ConstructorStackTrace.java:39)
        at ConstructorStackTrace.main(ConstructorStackTrace.java:18)
InnerClass
java.lang.NullPointerException: hello
        at ConstructorStackTrace$InnerClass.<init>(ConstructorStackTrace.java:5)
        at ConstructorStackTrace.main(ConstructorStackTrace.java:24)

Where did these extra StackTraceElements come from? Is this something inserted by grpc? by grpc's logging (their logging has a different format tha mine)? The rest of my logs don't have these extra StackTraceElements. At first I thought I had the wrong version of the code, but three classes (MyProtoClass, MyProtoClass$1, AbstractParser) all follow this pattern, making it to much of a coincidence.

1 Answers

If you look at the bytecode, it doesn't match the sourcecode. Some extra stuff was added. You can see if yourself by grabbing protobuf-java-3.20.0.jar, extracting the jar and running javap -c -l com/google/protobuf/AbstractParser.class

  public java.lang.Object parseFrom(com.google.protobuf.CodedInputStream, com.google.protobuf.ExtensionRegistryLite) throws com.google.protobuf.InvalidProtocolBufferException;
    Code:
       0: aload_0
       1: aload_1
       2: aload_2
       3: invokevirtual #14                 // Method parseFrom:(Lcom/google/protobuf/CodedInputStream;Lcom/google/protobuf/ExtensionRegistryLite;)Lcom/google/protobuf/MessageLite;
       6: areturn
    LineNumberTable:
      line 48: 0
    LocalVariableTable:
      Start  Length  Slot  Name   Signature
          0       7     0  this   Lcom/google/protobuf/AbstractParser;

Line number table points to 48 which is the line where the class definition begins...

The corresponding source code does not have any methods that return Object https://github.com/protocolbuffers/protobuf/blob/v3.20.0/java/core/src/main/java/com/google/protobuf/AbstractParser.java

The above bytecode calls the below bytecode which corresponds with the source code.

  public MessageType parseFrom(com.google.protobuf.CodedInputStream, com.google.protobuf.ExtensionRegistryLite) throws com.google.protobuf.InvalidProtocolBufferException;
    Code:
       0: aload_0
       1: aload_0
       2: aload_1
       3: aload_2
       4: invokevirtual #11                 // Method parsePartialFrom:(Lcom/google/protobuf/CodedInputStream;Lcom/google/protobuf/ExtensionRegistryLite;)Ljava/lang/Object;
       7: checkcast     #12                 // class com/google/protobuf/MessageLite
      10: invokespecial #13                 // Method checkMessageInitialized:(Lcom/google/protobuf/MessageLite;)Lcom/google/protobuf/MessageLite;
      13: areturn
    LineNumberTable:
      line 86: 0
    LocalVariableTable:
      Start  Length  Slot  Name   Signature
          0      14     0  this   Lcom/google/protobuf/AbstractParser;
          0      14     1 input   Lcom/google/protobuf/CodedInputStream;
          0      14     2 extensionRegistry   Lcom/google/protobuf/ExtensionRegistryLite;

This explains where the extra StackTraceElements came from. Now the question becomes, where did this extra bytecode come from?

Related