search

grpc / grpc-node

gRPC for Node.js
https://grpc.io
Apache License 2.0
4.47k stars 647 forks source link

Error: 13 INTERNAL: Response message parsing error: invalid wire type 7 at offset 89 #1892

Closed ashmortar closed 2 years ago

ashmortar commented 3 years ago

Problem description

Client is unable to parse response from server

Error: 13 INTERNAL: Response message parsing error: invalid wire type 7 at offset 89
    at Object.callErrorFromStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client.ts:338:36)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client-interceptors.ts:426:34)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client-interceptors.ts:387:48)
    at /Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/call-stream.ts:276:24
    at processTicksAndRejections (node:internal/process/task_queues:76:11)

Reproduction steps

I have created an image detection service that is the server here, with nestjs on the node side as the client. The proto file defining the relationship is:

syntax = "proto3";

package imageDetection;

service ImageDetectionService {
  rpc detect (DetectImageRequest) returns (DetectImageResponse) {}
}

message DetectImageRequest {
  string image = 1;
  string address = 2;
  float latitude = 3;
  float longitude = 4;
  string id =5;
}

message DetectImageResponse {

    message Totals {
        uint32 number_of_panels = 1;
        double annual_ac_production = 2;
    }

    message Points {
        double lat = 1;
        double lon = 2;
    }

    message Polygon {
        repeated Points points = 1;
    }

    message Inputs {
        string system_capacity = 1;
        string module_type = 2;
        string losses = 3;
        string array_type = 4;
        string tilt = 5;
        string azimuth = 6;
        string lat = 7;
        string lon = 8;
    }

    message Ssc_info {
        uint32 version = 1;
        string build = 2;
    }

    message Station_info {
        double lat = 1;
        double lon = 2;
        double elev = 3;
        double tz = 4;
        string location = 5;
        string city = 6;
        string state = 7;
        string solar_resource_file = 8;
        uint32 distance = 9;
    }

    message Outputs {
        repeated double ac_monthly = 1;
        repeated double poa_monthly = 2;
        repeated double solrad_monthly = 3;
        repeated double dc_monthly = 4;
        double ac_annual = 5;
        double solrad_annual = 6;
        double capacity_factor = 7;
    }

    message Production {
        Inputs inputs = 1;
        repeated string errors = 2;
        repeated string warnings = 3;
        string version = 4;
        Ssc_info ssc_info = 5;
        Station_info station_info = 6;
        Outputs outputs = 7;
    }

    message Arrays {
        string id = 1;
        string direction = 2;
        uint32 slope = 3;
        double azimuth = 4;
        Polygon roof_polygon = 5;
        repeated Polygon contained_panel_polygons = 6;
        repeated Polygon intersecting_panel_polygons = 7;
        repeated Polygon uncontained_panel_polygons = 8;
        Production production = 9;
    }

    Totals totals = 1;
    repeated Arrays arrays = 2;
    repeated Polygon trees = 3;
}

Which does fine when generating typescript interfaces for typing and also on the python side for generating the server stubs and classes. After spinning everything up I can send messages from the client, receive and process them but when deserializing the response the above error is thrown.

Environment

Additional context

full log of request-response:

2021-08-31T21:29:52.762Z | channel | dns:localhost:50051 createCall [0] method="/imageDetection.ImageDetectionService/detect", deadline=Infinity
2021-08-31T21:29:52.763Z | call_stream | [0] Sending metadata
2021-08-31T21:29:52.764Z | dns_resolver | Resolution update requested for target dns:localhost:50051
2021-08-31T21:29:52.765Z | resolving_load_balancer | dns:localhost:50051 IDLE -> CONNECTING
2021-08-31T21:29:52.765Z | connectivity_state | dns:localhost:50051 IDLE -> CONNECTING
2021-08-31T21:29:52.765Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.765Z | connectivity_state | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.765Z | channel | callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
2021-08-31T21:29:52.767Z | call_stream | [0] write() called with message of length 241423
2021-08-31T21:29:52.767Z | call_stream | [0] end() called
2021-08-31T21:29:52.768Z | call_stream | [0] deferring writing data chunk of length 241428
2021-08-31T21:29:52.769Z | dns_resolver | Resolved addresses for target dns:localhost:50051: [::1:50051,127.0.0.1:50051]
2021-08-31T21:29:52.772Z | pick_first | Connect to address list ::1:50051,127.0.0.1:50051
2021-08-31T21:29:52.773Z | subchannel_refcount | ::1:50051 refcount 0 -> 1
2021-08-31T21:29:52.773Z | subchannel_refcount | 127.0.0.1:50051 refcount 0 -> 1
2021-08-31T21:29:52.773Z | subchannel_refcount | ::1:50051 refcount 1 -> 2
2021-08-31T21:29:52.773Z | subchannel_refcount | 127.0.0.1:50051 refcount 1 -> 2
2021-08-31T21:29:52.773Z | pick_first | Start connecting to subchannel with address ::1:50051
2021-08-31T21:29:52.774Z | pick_first | IDLE -> CONNECTING
2021-08-31T21:29:52.774Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.774Z | channel | callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
2021-08-31T21:29:52.775Z | connectivity_state | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.775Z | subchannel | ::1:50051 IDLE -> CONNECTING
2021-08-31T21:29:52.776Z | pick_first | CONNECTING -> CONNECTING
2021-08-31T21:29:52.776Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.776Z | connectivity_state | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.777Z | channel | Pick result: QUEUE subchannel: undefined status: undefined undefined
2021-08-31T21:29:52.777Z | channel | callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2021-08-31T21:29:52.777Z | subchannel | 127.0.0.1:50051 IDLE -> CONNECTING
2021-08-31T21:29:52.777Z | pick_first | CONNECTING -> CONNECTING
2021-08-31T21:29:52.777Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.777Z | channel | callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2021-08-31T21:29:52.777Z | channel | Pick result: QUEUE subchannel: undefined status: undefined undefined
2021-08-31T21:29:52.777Z | channel | callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2021-08-31T21:29:52.777Z | connectivity_state | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.778Z | subchannel | ::1:50051 creating HTTP/2 session
2021-08-31T21:29:52.779Z | subchannel | 127.0.0.1:50051 creating HTTP/2 session
2021-08-31T21:29:52.783Z | subchannel | ::1:50051 connection closed with error connect ECONNREFUSED ::1:50051
2021-08-31T21:29:52.783Z | subchannel | ::1:50051 connection closed
2021-08-31T21:29:52.783Z | subchannel | ::1:50051 CONNECTING -> TRANSIENT_FAILURE
2021-08-31T21:29:52.784Z | pick_first | CONNECTING -> CONNECTING
2021-08-31T21:29:52.784Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.784Z | channel | callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2021-08-31T21:29:52.784Z | channel | Pick result: QUEUE subchannel: undefined status: undefined undefined
2021-08-31T21:29:52.784Z | channel | callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2021-08-31T21:29:52.784Z | connectivity_state | dns:localhost:50051 CONNECTING -> CONNECTING
2021-08-31T21:29:52.785Z | subchannel | 127.0.0.1:50051 CONNECTING -> READY
2021-08-31T21:29:52.786Z | pick_first | Pick subchannel with address 127.0.0.1:50051
2021-08-31T21:29:52.786Z | pick_first | CONNECTING -> READY
2021-08-31T21:29:52.786Z | resolving_load_balancer | dns:localhost:50051 CONNECTING -> READY
2021-08-31T21:29:52.786Z | channel | callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2021-08-31T21:29:52.786Z | channel | Pick result: COMPLETE subchannel: 127.0.0.1:50051 status: undefined undefined
2021-08-31T21:29:52.787Z | connectivity_state | dns:localhost:50051 CONNECTING -> READY
2021-08-31T21:29:52.787Z | subchannel_refcount | 127.0.0.1:50051 refcount 2 -> 3
2021-08-31T21:29:52.787Z | subchannel_refcount | ::1:50051 refcount 2 -> 1
2021-08-31T21:29:52.787Z | subchannel_refcount | 127.0.0.1:50051 refcount 3 -> 2
2021-08-31T21:29:52.790Z | call_stream | Starting stream on subchannel 127.0.0.1:50051 with headers
                grpc-accept-encoding: identity,deflate,gzip
                accept-encoding: identity
                :authority: localhost:50051
                user-agent: grpc-node-js/1.3.7
                content-type: application/grpc
                :method: POST
                :path: /imageDetection.ImageDetectionService/detect
                te: trailers

2021-08-31T21:29:52.791Z | call_stream | [0] attachHttp2Stream from subchannel 127.0.0.1:50051
2021-08-31T21:29:52.791Z | subchannel_refcount | 127.0.0.1:50051 callRefcount 0 -> 1
2021-08-31T21:29:52.791Z | call_stream | [0] sending data chunk of length 241428 (deferred)
2021-08-31T21:29:52.791Z | call_stream | [0] calling end() on HTTP/2 stream
2021-08-31T21:29:53.775Z | subchannel | ::1:50051 TRANSIENT_FAILURE -> CONNECTING
2021-08-31T21:29:53.776Z | subchannel | ::1:50051 creating HTTP/2 session
2021-08-31T21:29:53.777Z | subchannel | ::1:50051 connection closed with error connect ECONNREFUSED ::1:50051
2021-08-31T21:29:53.777Z | subchannel | ::1:50051 connection closed
2021-08-31T21:29:53.777Z | subchannel | ::1:50051 CONNECTING -> TRANSIENT_FAILURE
2021-08-31T21:29:53.777Z | subchannel | ::1:50051 TRANSIENT_FAILURE -> IDLE
2021-08-31T21:29:59.364Z | call_stream | [0] Received server headers:
                :status: 200
                content-type: application/grpc
                grpc-accept-encoding: identity,deflate,gzip
                accept-encoding: identity,gzip

2021-08-31T21:29:59.366Z | call_stream | [0] receive HTTP/2 data frame of length 16384
2021-08-31T21:29:59.367Z | call_stream | [0] receive HTTP/2 data frame of length 2523
2021-08-31T21:29:59.367Z | call_stream | [0] parsed message of length 18907
2021-08-31T21:29:59.367Z | call_stream | [0] filterReceivedMessage of length 18907
2021-08-31T21:29:59.368Z | call_stream | [0] pushing to reader message of length 18902
2021-08-31T21:29:59.373Z | call_stream | [0] cancelWithStatus code: 13 details: "Response message parsing error: invalid wire type 7 at offset 89"
2021-08-31T21:29:59.373Z | call_stream | [0] ended with status: code=13 details="Response message parsing error: invalid wire type 7 at offset 89"
2021-08-31T21:29:59.373Z | subchannel_refcount | 127.0.0.1:50051 callRefcount 1 -> 0
2021-08-31T21:29:59.374Z | call_stream | [0] close http2 stream with code 8
[Nest] 78951  - 08/31/2021, 2:29:59 PM   ERROR [ExceptionsHandler] 13 INTERNAL: Response message parsing error: invalid wire type 7 at offset 89
Error: 13 INTERNAL: Response message parsing error: invalid wire type 7 at offset 89
    at Object.callErrorFromStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/call.ts:81:24)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client.ts:338:36)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client-interceptors.ts:426:34)
    at Object.onReceiveStatus (/Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/client-interceptors.ts:387:48)
    at /Users/aaronross/eyecuelab/powur-vision-gateway/node_modules/@grpc/grpc-js/src/call-stream.ts:276:24
    at processTicksAndRejections (node:internal/process/task_queues:76:11)
2021-08-31T21:29:59.469Z | call_stream | [0] HTTP/2 stream closed with code 8
2021-08-31T21:30:02.774Z | subchannel_refcount | ::1:50051 refcount 1 -> 0
murgatroid99 commented 3 years ago

Unfortunately, the log doesn't tell us much about this error. The problem is with the contents of the message, which is not included in the log.

Would it be possible for you to dump the encoded message into a file on the server? That's probably the best bet for us to figure out what is happening here.