search

stepancheg / grpc-rust

Rust implementation of gRPC
MIT License
1.37k stars 124 forks source link

GRPC Internal error when trying to connect to Python server: "Missing :authority or :path" #105

Closed severin-lemaignan closed 6 years ago

severin-lemaignan commented 6 years ago

While the greeter example works well with both rust greeter clients & servers, or with a mix of go and rust clients & servers), I hit an 'InternalError' when I try to to use the Google-provided Python greeter server.

Python server output obtained with export GRPC_VERBOSITY=DEBUG and export GRPC_TRACE=http:

D1225 21:24:11.393728793   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
D1225 21:24:11.393766213   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING -> WRITING+MORE [INITIAL_WRITE]
D1225 21:24:11.393803032   23087 writing.cc:104]             SERVER: Ping sent [0x7f5f30000f50]: 0/0
D1225 21:24:11.393817170   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING+MORE -> WRITING [begin write in current thread]
D1225 21:24:11.393861848   23087 chttp2_transport.cc:2599]   ipv4:127.0.0.1:50642: Start BDP ping err="No Error"
D1225 21:24:11.393870132   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING -> IDLE [finish writing]
D1225 21:24:11.393891249   23087 frame_settings.cc:220]      CHTTP2:SVR:ipv4:127.0.0.1:50642: got setting ENABLE_PUSH = 0
I1225 21:24:11.394156826   23087 parsing.cc:648]             parsing initial_metadata
D1225 21:24:11.394172033   23087 hpack_parser.cc:663]        Decode: ':method: POST', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:24:11.394183240   23087 parsing.cc:424]             HTTP:1:HDR:SVR: :method: 50 4f 53 54 'POST'
D1225 21:24:11.394190013   23087 hpack_parser.cc:663]        Decode: ':path: /helloworld.Greeter/SayHello', elem_interned=0 [2], k_interned=1, v_interned=0
I1225 21:24:11.394196117   23087 parsing.cc:424]             HTTP:1:HDR:SVR: :path: 2f 68 65 6c 6c 6f 77 6f 72 6c 64 2e 47 72 65 65 74 65 72 2f 53 61 79 48 65 6c 6c 6f '/helloworld.Greeter/SayHello'
D1225 21:24:11.394201765   23087 hpack_parser.cc:663]        Decode: ':authority: localhost', elem_interned=0 [2], k_interned=1, v_interned=0
I1225 21:24:11.394206559   23087 parsing.cc:424]             HTTP:1:HDR:SVR: :authority: 6c 6f 63 61 6c 68 6f 73 74 'localhost'
D1225 21:24:11.394211004   23087 hpack_parser.cc:663]        Decode: ':scheme: http', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:24:11.394215498   23087 parsing.cc:424]             HTTP:1:HDR:SVR: :scheme: 68 74 74 70 'http'
D1225 21:24:11.394220257   23087 hpack_parser.cc:663]        Decode: 'content-type: application/grpc', elem_interned=0 [2], k_interned=1, v_interned=0
I1225 21:24:11.394224901   23087 parsing.cc:424]             HTTP:1:HDR:SVR: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
D1225 21:24:11.394232205   23087 chttp2_transport.cc:1692]   perform_stream_op[s=0x7f5f3000d1e0]:  RECV_INITIAL_METADATA
D1225 21:24:11.394239324   23087 chttp2_transport.cc:1402]   perform_stream_op_locked:  RECV_INITIAL_METADATA; on_complete = 0x7f5f3000d0a0
D1225 21:24:11.394245525   23087 chttp2_transport.cc:1244]   complete_closure_step: t=0x7f5f30001960 0x7f5f3000d0a0 refs=0 flags=0x0000 desc=op->on_complete err="No Error" write_state=IDLE
D1225 21:24:11.394278937   23087 chttp2_transport.cc:1692]   perform_stream_op[s=0x7f5f3000d1e0]:  CANCEL:{"created":"@1514237051.394252787","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":748,"referenced_errors":[{"created":"@1514237051.394251536","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":91,"referenced_errors":[{"created":"@1514237051.394250761","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":146,"key":"te"}]}]}
D1225 21:24:11.394288335   23087 chttp2_transport.cc:1692]   perform_stream_op[s=0x7f5f3000d1e0]:  CANCEL:"Cancelled"
D1225 21:24:11.394302361   23087 chttp2_transport.cc:1402]   perform_stream_op_locked:  CANCEL:{"created":"@1514237051.394252787","description":"Missing :authority or :path","file":"src/core/lib/surface/server.cc","file_line":748,"referenced_errors":[{"created":"@1514237051.394251536","description":"Failed processing incoming headers","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":91,"referenced_errors":[{"created":"@1514237051.394250761","description":"Missing header","file":"src/core/ext/filters/http/server/http_server_filter.cc","file_line":146,"key":"te"}]}]}; on_complete = 0x7f5f30005fa0
D1225 21:24:11.394311215   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state IDLE -> WRITING [RST_STREAM]
D1225 21:24:11.394322888   23087 chttp2_transport.cc:1244]   complete_closure_step: t=0x7f5f30001960 0x7f5f30005fa0 refs=0 flags=0x0000 desc=op->on_complete err="No Error" write_state=WRITING
D1225 21:24:11.394329191   23087 chttp2_transport.cc:1402]   perform_stream_op_locked:  CANCEL:"Cancelled"; on_complete = 0x7f5f30005dd0
D1225 21:24:11.394334837   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING -> WRITING+MORE [CLOSE_FROM_API]
D1225 21:24:11.394339735   23087 chttp2_transport.cc:1244]   complete_closure_step: t=0x7f5f30001960 0x7f5f30005dd0 refs=0 flags=0x0000 desc=op->on_complete err="No Error" write_state=WRITING+MORE
D1225 21:24:11.394351006   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING+MORE -> WRITING [begin write in current thread]
D1225 21:24:11.394376495   23087 chttp2_transport.cc:845]    W:0x7f5f30001960 SERVER state WRITING -> IDLE [finish writing]
D1225 21:24:11.394442221   23087 chttp2_transport.cc:2613]   ipv4:127.0.0.1:50642: Complete BDP ping err="No Error"
D1225 21:24:11.394921459   23087 chttp2_transport.cc:2788]   set connectivity_state=4

Steps to reproduce:

severin-lemaignan commented 6 years ago

For the sake of completeness, the error does not occur if I use go's greeter_client example.

GRPC output when go's greeter_client connects:

D1225 21:33:43.237934433   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
D1225 21:33:43.237959744   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> WRITING+MORE [INITIAL_WRITE]
D1225 21:33:43.237997342   23448 writing.cc:104]             SERVER: Ping sent [0x7fa4e4005860]: 0/0
D1225 21:33:43.238007736   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING+MORE -> WRITING [begin write in current thread]
D1225 21:33:43.238059872   23448 chttp2_transport.cc:2599]   ipv4:127.0.0.1:50778: Start BDP ping err="No Error"
D1225 21:33:43.238068590   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> IDLE [finish writing]
I1225 21:33:43.238328820   23448 parsing.cc:648]             parsing initial_metadata
D1225 21:33:43.238343697   23448 hpack_parser.cc:663]        Decode: ':method: POST', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:33:43.238349915   23448 parsing.cc:424]             HTTP:1:HDR:SVR: :method: 50 4f 53 54 'POST'
D1225 21:33:43.238357188   23448 hpack_parser.cc:663]        Decode: ':scheme: http', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:33:43.238365389   23448 parsing.cc:424]             HTTP:1:HDR:SVR: :scheme: 68 74 74 70 'http'
D1225 21:33:43.238382708   23448 hpack_parser.cc:663]        Decode: ':path: /helloworld.Greeter/SayHello', elem_interned=1 [1], k_interned=1, v_interned=1
I1225 21:33:43.238395705   23448 parsing.cc:424]             HTTP:1:HDR:SVR: :path: 2f 68 65 6c 6c 6f 77 6f 72 6c 64 2e 47 72 65 65 74 65 72 2f 53 61 79 48 65 6c 6c 6f '/helloworld.Greeter/SayHello'
D1225 21:33:43.238409113   23448 hpack_parser.cc:663]        Decode: ':authority: localhost:50051', elem_interned=1 [1], k_interned=1, v_interned=1
I1225 21:33:43.238419345   23448 parsing.cc:424]             HTTP:1:HDR:SVR: :authority: 6c 6f 63 61 6c 68 6f 73 74 3a 35 30 30 35 31 'localhost:50051'
D1225 21:33:43.238430603   23448 hpack_parser.cc:663]        Decode: 'content-type: application/grpc', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:33:43.238441229   23448 parsing.cc:424]             HTTP:1:HDR:SVR: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
D1225 21:33:43.238453511   23448 hpack_parser.cc:663]        Decode: 'user-agent: grpc-go/1.9.0-dev', elem_interned=1 [1], k_interned=1, v_interned=1
I1225 21:33:43.238464252   23448 parsing.cc:424]             HTTP:1:HDR:SVR: user-agent: 67 72 70 63 2d 67 6f 2f 31 2e 39 2e 30 2d 64 65 76 'grpc-go/1.9.0-dev'
D1225 21:33:43.238476963   23448 hpack_parser.cc:663]        Decode: 'te: trailers', elem_interned=1 [3], k_interned=1, v_interned=1
I1225 21:33:43.238487327   23448 parsing.cc:424]             HTTP:1:HDR:SVR: te: 74 72 61 69 6c 65 72 73 'trailers'
D1225 21:33:43.238504834   23448 chttp2_transport.cc:1692]   perform_stream_op[s=0x7fa4e400d230]:  RECV_INITIAL_METADATA
D1225 21:33:43.238518002   23448 chttp2_transport.cc:2613]   ipv4:127.0.0.1:50778: Complete BDP ping err="No Error"
D1225 21:33:43.238536346   23448 chttp2_transport.cc:1402]   perform_stream_op_locked:  RECV_INITIAL_METADATA; on_complete = 0x7fa4e400d0f0
D1225 21:33:43.238549109   23448 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d0f0 refs=0 flags=0x0000 desc=op->on_complete err="No Error" write_state=IDLE
D1225 21:33:43.238706203   23448 chttp2_transport.cc:1692]   perform_stream_op[s=0x7fa4e400d230]:  RECV_TRAILING_METADATA COLLECT_STATS:0x7fa4e400c5e8
D1225 21:33:43.238718321   23448 chttp2_transport.cc:1402]   perform_stream_op_locked:  RECV_TRAILING_METADATA COLLECT_STATS:0x7fa4e400c5e8; on_complete = 0x7fa4e400d170
D1225 21:33:43.238730437   23448 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d170 refs=1 flags=0x0001 desc=op->on_complete err="No Error" write_state=IDLE
D1225 21:33:43.239085552   23488 chttp2_transport.cc:1692]   perform_stream_op[s=0x7fa4e400d230]:  RECV_MESSAGE
D1225 21:33:43.239110112   23488 chttp2_transport.cc:1402]   perform_stream_op_locked:  RECV_MESSAGE; on_complete = 0x7fa4e400d130
D1225 21:33:43.239123962   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d130 refs=0 flags=0x0000 desc=op->on_complete err="No Error" write_state=IDLE
D1225 21:33:43.239353960   23488 chttp2_transport.cc:1692]   perform_stream_op[s=0x7fa4e400d230]:  SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_MESSAGE:flags=0x00000000:len=14 SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}
D1225 21:33:43.239386190   23488 chttp2_transport.cc:1402]   perform_stream_op_locked:  SEND_INITIAL_METADATA{key=3a 73 74 61 74 75 73 ':status' value=32 30 30 '200', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_MESSAGE:flags=0x00000000:len=14 SEND_TRAILING_METADATA{key=67 72 70 63 2d 73 74 61 74 75 73 'grpc-status' value=30 '0', key=67 72 70 63 2d 6d 65 73 73 61 67 65 'grpc-message' value=}; on_complete = 0x7fa4e400d030
I1225 21:33:43.239397692   23488 chttp2_transport.cc:1381]   HTTP:1:HDR:SVR: :status: 200
I1225 21:33:43.239406310   23488 chttp2_transport.cc:1381]   HTTP:1:HDR:SVR: content-type: application/grpc
I1225 21:33:43.239413755   23488 chttp2_transport.cc:1381]   HTTP:1:HDR:SVR: grpc-accept-encoding: identity,deflate,gzip
I1225 21:33:43.239421812   23488 chttp2_transport.cc:1381]   HTTP:1:HDR:SVR: accept-encoding: identity,gzip
I1225 21:33:43.239429948   23488 chttp2_transport.cc:1381]   HTTP:1:TRL:SVR: grpc-status: 0
I1225 21:33:43.239437503   23488 chttp2_transport.cc:1381]   HTTP:1:TRL:SVR: grpc-message: 
D1225 21:33:43.239445613   23488 stream_lists.cc:123]        0x7fa4e4001960[1][svr]: add to writable
D1225 21:33:43.239453126   23488 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state IDLE -> WRITING [SEND_INITIAL_METADATA]
D1225 21:33:43.239462590   23488 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> WRITING+MORE [SEND_MESSAGE]
D1225 21:33:43.239472920   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d030 refs=3 flags=0x0002 desc=op->on_complete err="No Error" write_state=WRITING+MORE
D1225 21:33:43.239481828   23488 stream_lists.cc:69]         0x7fa4e4001960[1][svr]: pop from writable
D1225 21:33:43.239488746   23488 writing.cc:399]             W:0x7fa4e4001960 SERVER[1] im-(sent,send)=(0,1) announce=0
D1225 21:33:43.239497421   23488 hpack_encoder.cc:485]       Encode: ':status: 200', elem_interned=1 [3], k_interned=1, v_interned=1
D1225 21:33:43.239508760   23488 hpack_encoder.cc:485]       Encode: 'content-type: application/grpc', elem_interned=1 [3], k_interned=1, v_interned=1
D1225 21:33:43.239518518   23488 hpack_encoder.cc:485]       Encode: 'grpc-accept-encoding: identity,deflate,gzip', elem_interned=1 [3], k_interned=1, v_interned=1
D1225 21:33:43.239527898   23488 hpack_encoder.cc:485]       Encode: 'accept-encoding: identity,gzip', elem_interned=1 [3], k_interned=1, v_interned=1
D1225 21:33:43.239537281   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d030 refs=2 flags=0x0002 desc=send_initial_metadata_finished err="No Error" write_state=WRITING+MORE
D1225 21:33:43.239566350   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d030 refs=1 flags=0x0002 desc=finish_write_cb err="No Error" write_state=WRITING+MORE
I1225 21:33:43.239573108   23488 writing.cc:507]             sending trailing_metadata
D1225 21:33:43.239581106   23488 hpack_encoder.cc:485]       Encode: 'grpc-status: 0', elem_interned=1 [3], k_interned=1, v_interned=1
D1225 21:33:43.239590486   23488 hpack_encoder.cc:485]       Encode: 'grpc-message: ', elem_interned=0 [2], k_interned=1, v_interned=0
D1225 21:33:43.239600376   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d030 refs=0 flags=0x0002 desc=send_trailing_metadata_finished err="No Error" write_state=WRITING+MORE
D1225 21:33:43.239610554   23488 chttp2_transport.cc:1244]   complete_closure_step: t=0x7fa4e4001960 0x7fa4e400d170 refs=0 flags=0x0001 desc=recv_trailing_metadata_finished err="No Error" write_state=WRITING+MORE
D1225 21:33:43.239618402   23488 stream_lists.cc:123]        0x7fa4e4001960[1][svr]: add to writing
D1225 21:33:43.239626184   23488 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING+MORE -> WRITING [begin write in current thread]
D1225 21:33:43.239680377   23488 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> IDLE [finish writing]
D1225 21:33:43.239692532   23488 stream_lists.cc:69]         0x7fa4e4001960[1][svr]: pop from writing
D1225 21:33:43.239857622   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state IDLE -> WRITING [PING_RESPONSE]
D1225 21:33:43.239874732   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> WRITING [begin write in current thread]
D1225 21:33:43.239912833   23448 chttp2_transport.cc:845]    W:0x7fa4e4001960 SERVER state WRITING -> IDLE [finish writing]
D1225 21:33:43.240359272   23448 chttp2_transport.cc:2788]   set connectivity_state=4