[CALCITE-982] Improve debug-ability when failing to parse serialized messages over RPC

• Type: Improvement
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Component/s: avatica
• Assignee: Josh Elser
• Reporter: Josh Elser
• Created: 18/Nov/15 21:14
• Updated: 18/Jun/21 08:31

Description

A pain that I keep running into while running some higher-level tests with Phoenix is that when the client or server cannot parse a message over HTTP, there's a very unhelpful message that is printed.

For example, with protobuf:

java.lang.RuntimeException: org.apache.calcite.avatica.com.google.protobuf.InvalidProtocolBufferException: Protocol message end-group tag did not match expected tag.
        at org.apache.calcite.avatica.remote.RemoteProtobufService._apply(RemoteProtobufService.java:41)
        at org.apache.calcite.avatica.remote.ProtobufService.apply(ProtobufService.java:75)
        at org.apache.calcite.avatica.remote.RemoteMeta$1.call(RemoteMeta.java:88)
        at org.apache.calcite.avatica.remote.RemoteMeta$1.call(RemoteMeta.java:84)
        at org.apache.calcite.avatica.AvaticaConnection.invokeWithRetries(AvaticaConnection.java:666)
        at org.apache.calcite.avatica.remote.RemoteMeta.createStatement(RemoteMeta.java:83)
        at org.apache.calcite.avatica.AvaticaStatement.<init>(AvaticaStatement.java:108)
        at org.apache.calcite.avatica.AvaticaStatement.<init>(AvaticaStatement.java:94)
        at org.apache.calcite.avatica.AvaticaJdbc41Factory$AvaticaJdbc41Statement.<init>(AvaticaJdbc41Factory.java:114)
        at org.apache.calcite.avatica.AvaticaJdbc41Factory.newStatement(AvaticaJdbc41Factory.java:73)
        at org.apache.calcite.avatica.AvaticaConnection.createStatement(AvaticaConnection.java:300)
        at org.apache.calcite.avatica.AvaticaConnection.createStatement(AvaticaConnection.java:146)
        at org.apache.calcite.avatica.MetaImpl.createResultSet(MetaImpl.java:256)
        at org.apache.calcite.avatica.MetaImpl.createEmptyResultSet(MetaImpl.java:215)
        at org.apache.calcite.avatica.MetaImpl.getPrimaryKeys(MetaImpl.java:657)
        at org.apache.calcite.avatica.AvaticaDatabaseMetaData$18.call(AvaticaDatabaseMetaData.java:906)
        at org.apache.calcite.avatica.AvaticaDatabaseMetaData$18.call(AvaticaDatabaseMetaData.java:903)
        at org.apache.calcite.avatica.AvaticaConnection.invokeWithRetries(AvaticaConnection.java:666)
        at org.apache.calcite.avatica.AvaticaDatabaseMetaData.getPrimaryKeys(AvaticaDatabaseMetaData.java:902)
        at sqlline.Rows.isPrimaryKey(Rows.java:78)
        at sqlline.TableOutputFormat.getOutputString(TableOutputFormat.java:106)
        at sqlline.TableOutputFormat.getOutputString(TableOutputFormat.java:91)
        at sqlline.TableOutputFormat.print(TableOutputFormat.java:35)
        at sqlline.SqlLine.print(SqlLine.java:1653)
        at sqlline.Commands.execute(Commands.java:833)
        at sqlline.Commands.sql(Commands.java:732)
        at sqlline.SqlLine.dispatch(SqlLine.java:808)
        at sqlline.SqlLine.runCommands(SqlLine.java:1711)
        at sqlline.Commands.run(Commands.java:1285)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at sqlline.ReflectiveCommandHandler.execute(ReflectiveCommandHandler.java:36)
        at sqlline.SqlLine.dispatch(SqlLine.java:804)
        at sqlline.SqlLine.initArgs(SqlLine.java:613)
        at sqlline.SqlLine.begin(SqlLine.java:656)
        at sqlline.SqlLine.start(SqlLine.java:398)
        at sqlline.SqlLine.main(SqlLine.java:292)
Caused by: org.apache.calcite.avatica.com.google.protobuf.InvalidProtocolBufferException: Protocol message end-group tag did not match expected tag.
        at org.apache.calcite.avatica.com.google.protobuf.InvalidProtocolBufferException.invalidEndTag(InvalidProtocolBufferException.java:94)
        at org.apache.calcite.avatica.com.google.protobuf.CodedInputStream.checkLastTagWas(CodedInputStream.java:174)
        at org.apache.calcite.avatica.com.google.protobuf.AbstractParser.parsePartialFrom(AbstractParser.java:139)
        at org.apache.calcite.avatica.com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:168)
        at org.apache.calcite.avatica.com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:180)
        at org.apache.calcite.avatica.com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:185)
        at org.apache.calcite.avatica.com.google.protobuf.AbstractParser.parseFrom(AbstractParser.java:49)
        at org.apache.calcite.avatica.proto.Common$WireMessage.parseFrom(Common.java:11760)
        at org.apache.calcite.avatica.remote.ProtobufTranslationImpl.parseResponse(ProtobufTranslationImpl.java:229)
        at org.apache.calcite.avatica.remote.RemoteProtobufService._apply(RemoteProtobufService.java:38)
        ... 38 more

Similarly, I recall seeing a equivalently unhelpful message with JSON about an invalid character. It would be nice to provide some better error message that allows us to retrospectively figure out what exactly was sent over the wire (and better reason about why the failure happened).