D0805 08:43:33.447314865 15613 test_config.c:278] test slowdown: machine=1.000000 build=1.000000 total=1.000000 D0805 08:43:33.447537571 15613 ev_posix.c:106] Using polling engine: poll I0805 08:43:33.447584570 15613 init.c:193] grpc_init(void) I0805 08:43:33.447638950 15613 init.c:193] grpc_init(void) I0805 08:43:33.447757064 15613 test_tcp_server.c:85] test tcp server listening on 0.0.0.0:45613 I0805 08:43:33.447810285 15613 completion_queue.c:139] grpc_completion_queue_create(reserved=(nil)) I0805 08:43:33.447829893 15613 channel_create.c:235] grpc_insecure_channel_create(target=0x138b480, args=(nil), reserved=(nil)) D0805 08:43:33.447930852 15614 bad_server_response_test.c:248] done=0, time_left=9.999999388 I0805 08:43:33.447944584 15613 channel.c:231] grpc_channel_create_call(channel=0x138c400, parent_call=(nil), propagation_mask=ffff, cq=0x138bfe0, method=/Service/Method, host=localhost, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil)) D0805 08:43:33.447975520 15614 bad_server_response_test.c:248] done=0, time_left=9.999865743 I0805 08:43:33.448013023 15613 metadata_array.c:42] grpc_metadata_array_init(array=0x7ffddfe6ca40) I0805 08:43:33.448027799 15613 metadata_array.c:42] grpc_metadata_array_init(array=0x7ffddfe6ca60) I0805 08:43:33.448042145 15613 call.c:1710] grpc_call_start_batch(call=0x138c950, ops=0x7ffddfe6ca80, nops=4, tag=0x1, reserved=(nil)) I0805 08:43:33.448056516 15613 call.c:1385] ops[0]: SEND_INITIAL_METADATA I0805 08:43:33.448065268 15613 call.c:1385] ops[1]: SEND_CLOSE_FROM_CLIENT I0805 08:43:33.448073515 15613 call.c:1385] ops[2]: RECV_INITIAL_METADATA ptr=0x7ffddfe6ca40 I0805 08:43:33.448083789 15613 call.c:1385] ops[3]: RECV_STATUS_ON_CLIENT metadata=0x7ffddfe6ca60 status=0x7ffddfe6ca18 details=0x7ffddfe6ca20 I0805 08:43:33.448124431 15613 client_channel.c:109] OP[client-channel:0x138cf58]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 '/Service/Method', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=6c 6f 63 61 6c 68 6f 73 74 'localhost', key=67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 'grpc-encoding' value=69 64 65 6e 74 69 74 79 'identity', 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'} SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_TRAILING_METADATA I0805 08:43:33.448365211 15613 completion_queue.c:333] grpc_completion_queue_next(cc=0x138bfe0, deadline=gpr_timespec { tv_sec: 122011, tv_nsec: 739283192, clock_type: 0 }, reserved=(nil)) D0805 08:43:33.448440355 15615 connectivity_state.c:92] CONWATCH: 0x7fc64c000a98 (null): get IDLE D0805 08:43:33.448457342 15615 connectivity_state.c:156] SET: 0x138c548 client_channel: IDLE --> IDLE [new_lb+resolver] error=(nil) null D0805 08:43:33.448466796 15615 connectivity_state.c:109] CONWATCH: 0x7fc64c000a98 (null): from IDLE [cur=IDLE] notify=0x7fc64c001198 D0805 08:43:33.448479351 15615 connectivity_state.c:109] CONWATCH: 0x7fc64c000de8 subchannel: from IDLE [cur=IDLE] notify=0x7fc64c001318 D0805 08:43:33.448488358 15615 connectivity_state.c:156] SET: 0x7fc64c000de8 subchannel: IDLE --> CONNECTING [state_change] error=(nil) null D0805 08:43:33.448495563 15615 connectivity_state.c:183] NOTIFY: 0x7fc64c001318 D0805 08:43:33.448614980 15615 tcp_client_posix.c:305] CLIENT_CONNECT: ipv4:127.0.0.1:45613: asynchronously connecting D0805 08:43:33.448639642 15615 connectivity_state.c:156] SET: 0x7fc64c000a98 (null): IDLE --> CONNECTING [connecting_changed] error=(nil) null D0805 08:43:33.448648397 15615 connectivity_state.c:183] NOTIFY: 0x7fc64c001198 D0805 08:43:33.448657140 15615 connectivity_state.c:109] CONWATCH: 0x7fc64c000de8 subchannel: from CONNECTING [cur=CONNECTING] notify=0x7fc64c001318 D0805 08:43:33.448657410 15614 tcp_server_posix.c:404] SERVER_CONNECT: incoming connection: ipv4:127.0.0.1:53009 D0805 08:43:33.448685405 15613 tcp_client_posix.c:135] CLIENT_CONNECT: ipv4:127.0.0.1:45613: on_writable: error=null D0805 08:43:33.448676580 15615 connectivity_state.c:156] SET: 0x138c548 client_channel: IDLE --> CONNECTING [lb_changed] error=(nil) null D0805 08:43:33.448730034 15613 tcp_client_posix.c:104] CLIENT_CONNECT: ipv4:127.0.0.1:45613: on_alarm: error="Cancelled" D0805 08:43:33.448742924 15615 connectivity_state.c:109] CONWATCH: 0x7fc64c000a98 (null): from CONNECTING [cur=CONNECTING] notify=0x7fc64c001258 D0805 08:43:33.448718906 15614 bad_server_response_test.c:248] done=0, time_left=9.999122687 D0805 08:43:33.448778972 15614 bad_server_response_test.c:248] done=0, time_left=9.999064868 D0805 08:43:33.448805078 15613 chttp2_transport.c:675] W:0x138de70 INACTIVE -> REQUESTED[p=0] because initial_write D0805 08:43:33.448841314 15613 chttp2_transport.c:675] W:0x138de70 REQUESTED[p=0] -> WRITING because start_writing D0805 08:43:33.448863684 15613 parsing.c:166] FLOW parsed: client transport CREDIT global.announce_incoming_window(0) by announce_bytes(983041) giving 983041 D0805 08:43:33.448876724 15613 parsing.c:168] FLOW parsed: client transport CREDIT parsing.incoming_window(65535) by announce_bytes(983041) giving 1048576 D0805 08:43:33.448884955 15613 chttp2_transport.c:675] W:0x138de70 WRITING -> WRITING[p=0] because global incoming window D0805 08:43:33.448900882 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 'PRI * HTTP/2.0....SM....' D0805 08:43:33.448913221 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 18 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 00 ff ff 00 06 00 00 40 00 '...............................@.' D0805 08:43:33.448990375 15613 connectivity_state.c:109] CONWATCH: 0x13901c0 client_transport: from READY [cur=READY] notify=0x138de10 D0805 08:43:33.449005805 15613 connectivity_state.c:156] SET: 0x7fc64c000de8 subchannel: CONNECTING --> READY [connected] error=(nil) null D0805 08:43:33.449012376 15614 tcp_posix.c:168] read: error=null D0805 08:43:33.449013365 15613 connectivity_state.c:183] NOTIFY: 0x7fc64c001318 D0805 08:43:33.449062479 15614 tcp_posix.c:173] READ 0x7fc654000b90 (peer=ipv4:127.0.0.1:53009): 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 00 00 18 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 00 ff ff 00 06 00 00 40 00 'PRI * HTTP/2.0....SM...................................@.' D0805 08:43:33.449092484 15614 bad_server_response_test.c:124] Server received: 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 00 00 18 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 00 ff ff 00 06 00 00 40 00 'PRI * HTTP/2.0....SM...................................@.' D0805 08:43:33.449075211 15613 chttp2_transport.c:675] W:0x138de70 WRITING[p=0] -> REQUESTED[p=0] because terminate_writing D0805 08:43:33.449129682 15613 writing.c:167] FLOW write: client transport DEBIT global.announce_incoming_window(983041) by announced(983041) giving 0 D0805 08:43:33.449145158 15613 chttp2_transport.c:675] W:0x138de70 REQUESTED[p=0] -> WRITING because start_writing D0805 08:43:33.449105085 15614 bad_server_response_test.c:128] got 57 bytes, expected 310 bytes D0805 08:43:33.449155725 15613 connectivity_state.c:156] SET: 0x7fc64c000a98 (null): CONNECTING --> READY [connecting_ready] error=(nil) null D0805 08:43:33.449181600 15613 connectivity_state.c:183] NOTIFY: 0x7fc64c001258 D0805 08:43:33.449192323 15613 connectivity_state.c:109] CONWATCH: 0x13901c0 client_transport: from READY [cur=READY] notify=0x7fc64c000a28 D0805 08:43:33.449186356 15614 bad_server_response_test.c:248] done=0, time_left=9.998657937 D0805 08:43:33.449217688 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 04 08 00 00 00 00 00 00 0f 00 01 '.............' D0805 08:43:33.449269183 15613 connectivity_state.c:156] SET: 0x138c548 client_channel: CONNECTING --> READY [lb_changed] error=(nil) null D0805 08:43:33.449281745 15613 connectivity_state.c:109] CONWATCH: 0x7fc64c000a98 (null): from READY [cur=READY] notify=0x138c338 D0805 08:43:33.449289217 15614 tcp_posix.c:168] read: error=null D0805 08:43:33.449300711 15613 chttp2_transport.c:675] W:0x138de70 WRITING -> INACTIVE because terminate_writing D0805 08:43:33.449310719 15614 tcp_posix.c:173] READ 0x7fc654000b90 (peer=ipv4:127.0.0.1:53009): 00 00 04 08 00 00 00 00 00 00 0f 00 01 '.............' D0805 08:43:33.449324922 15614 bad_server_response_test.c:124] Server received: 00 00 04 08 00 00 00 00 00 00 0f 00 01 '.............' I0805 08:43:33.449335740 15613 http_client_filter.c:171] OP[http-client:0x1390638]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 '/Service/Method', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=6c 6f 63 61 6c 68 6f 73 74 'localhost', key=67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 'grpc-encoding' value=69 64 65 6e 74 69 74 79 'identity', 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'} SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_TRAILING_METADATA D0805 08:43:33.449337461 15614 bad_server_response_test.c:128] got 70 bytes, expected 310 bytes D0805 08:43:33.449366366 15614 bad_server_response_test.c:248] done=0, time_left=9.998474996 I0805 08:43:33.449391274 15613 connected_channel.c:70] OP[connected:0x1390650]: SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 '/Service/Method', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=6c 6f 63 61 6c 68 6f 73 74 'localhost', key=67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 'grpc-encoding' value=69 64 65 6e 74 69 74 79 'identity', 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=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', 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=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 63 2f 31 2e 31 2e 30 2d 64 65 76 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c/1.1.0-dev (linux; chttp2)'} SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_TRAILING_METADATA D0805 08:43:33.449404607 15613 chttp2_transport.c:1037] HTTP:CLI: Allocating new grpc_chttp2_stream 0x1390768 to id 1 D0805 08:43:33.449413510 15613 chttp2_transport.c:675] W:0x138de70 INACTIVE -> REQUESTED[p=1] because new_stream D0805 08:43:33.449422406 15613 chttp2_transport.c:675] W:0x138de70 REQUESTED[p=1] -> SCHEDULED because unlocking D0805 08:43:33.449440580 15613 writing.c:98] FLOW write: client stream[1] MOVE writing.outgoing_window(0) <- global.outgoing_window(65535) giving 65535 D0805 08:43:33.449449469 15613 chttp2_transport.c:675] W:0x138de70 SCHEDULED -> WRITING because start_writing D0805 08:43:33.449477526 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 e6 01 04 00 00 00 01 40 07 '.........@.' D0805 08:43:33.449486825 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 3a 73 63 68 65 6d 65 ':scheme' D0805 08:43:33.449501970 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 04 '.' D0805 08:43:33.449510296 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 68 74 74 70 'http' D0805 08:43:33.449517967 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 07 '@.' D0805 08:43:33.449525515 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 3a 6d 65 74 68 6f 64 ':method' D0805 08:43:33.449532561 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 04 '.' D0805 08:43:33.449539875 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 50 4f 53 54 'POST' D0805 08:43:33.449547152 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 05 '@.' D0805 08:43:33.449554562 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 3a 70 61 74 68 ':path' D0805 08:43:33.449561490 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 0f '.' D0805 08:43:33.449571221 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 '/Service/Method' D0805 08:43:33.449579131 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 0a '@.' D0805 08:43:33.449587110 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 3a 61 75 74 68 6f 72 69 74 79 ':authority' D0805 08:43:33.449595111 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 09 6c 6f 63 61 6c 68 6f 73 74 40 0d '.localhost@.' D0805 08:43:33.449602971 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 'grpc-encoding' D0805 08:43:33.449609977 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 08 '.' D0805 08:43:33.449617545 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 69 64 65 6e 74 69 74 79 'identity' D0805 08:43:33.449624775 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 14 '@.' D0805 08:43:33.449633976 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' D0805 08:43:33.449641215 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 15 '.' D0805 08:43:33.449650298 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip' D0805 08:43:33.449658585 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 02 '@.' D0805 08:43:33.449666155 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 74 65 'te' D0805 08:43:33.449673262 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 08 '.' D0805 08:43:33.449681042 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 74 72 61 69 6c 65 72 73 'trailers' D0805 08:43:33.449688164 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 0c '@.' D0805 08:43:33.449695980 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' D0805 08:43:33.449702986 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 10 '.' D0805 08:43:33.449711703 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc' D0805 08:43:33.449719038 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 40 0a '@.' D0805 08:43:33.449726944 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 75 73 65 72 2d 61 67 65 6e 74 'user-agent' D0805 08:43:33.449733914 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 20 ' ' D0805 08:43:33.449751581 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 67 72 70 63 2d 63 2f 31 2e 31 2e 30 2d 64 65 76 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c/1.1.0-dev (linux; chttp2)' D0805 08:43:33.449760640 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 00 00 01 00 00 00 01 '.........' D0805 08:43:33.449807218 15613 chttp2_transport.c:675] W:0x138de70 WRITING -> INACTIVE because terminate_writing D0805 08:43:33.449835435 15614 tcp_posix.c:168] read: error=null D0805 08:43:33.449882677 15614 tcp_posix.c:173] READ 0x7fc654000b90 (peer=ipv4:127.0.0.1:53009): 00 00 e6 01 04 00 00 00 01 40 07 3a 73 63 68 65 6d 65 04 68 74 74 70 40 07 3a 6d 65 74 68 6f 64 04 50 4f 53 54 40 05 3a 70 61 74 68 0f 2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 40 0a 3a 61 75 74 68 6f 72 69 74 79 09 6c 6f 63 61 6c 68 6f 73 74 40 0d 67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 08 69 64 65 6e 74 69 74 79 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 15 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 40 02 74 65 08 74 72 61 69 6c 65 72 73 40 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 40 0a 75 73 65 72 2d 61 67 65 6e 74 20 67 72 70 63 2d 63 2f 31 2e 31 2e 30 2d 64 65 76 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 00 00 00 00 01 00 00 00 01 '.........@.:scheme.http@.:method.POST@.:path./Service/Method@.:authority.localhost@.grpc-encoding.identity@.grpc-accept-encoding.identity,deflate,gzip@.te.trailers@.content-type.application/grpc@.user-agent grpc-c/1.1.0-dev (linux; chttp2).........' D0805 08:43:33.449913316 15614 bad_server_response_test.c:124] Server received: 00 00 e6 01 04 00 00 00 01 40 07 3a 73 63 68 65 6d 65 04 68 74 74 70 40 07 3a 6d 65 74 68 6f 64 04 50 4f 53 54 40 05 3a 70 61 74 68 0f 2f 53 65 72 76 69 63 65 2f 4d 65 74 68 6f 64 40 0a 3a 61 75 74 68 6f 72 69 74 79 09 6c 6f 63 61 6c 68 6f 73 74 40 0d 67 72 70 63 2d 65 6e 63 6f 64 69 6e 67 08 69 64 65 6e 74 69 74 79 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 15 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 40 02 74 65 08 74 72 61 69 6c 65 72 73 40 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 40 0a 75 73 65 72 2d 61 67 65 6e 74 20 67 72 70 63 2d 63 2f 31 2e 31 2e 30 2d 64 65 76 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 00 00 00 00 01 00 00 00 01 '.........@.:scheme.http@.:method.POST@.:path./Service/Method@.:authority.localhost@.grpc-encoding.identity@.grpc-accept-encoding.identity,deflate,gzip@.te.trailers@.content-type.application/grpc@.user-agent grpc-c/1.1.0-dev (linux; chttp2).........' D0805 08:43:33.449924732 15614 bad_server_response_test.c:128] got 318 bytes, expected 310 bytes D0805 08:43:33.449940388 15614 tcp_posix.c:405] WRITE 0x7fc654000b90 (peer=ipv4:127.0.0.1:53009): 00 00 00 04 00 00 00 00 00 00 00 3e 01 04 00 00 00 01 10 0e 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 01 30 10 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 10 07 3a 73 74 61 74 75 73 03 32 30 34 '...........>........content-length.0..content-type.application/grpc..:status.204' D0805 08:43:33.450001354 15614 bad_server_response_test.c:248] done=1, time_left=9.997840859 D0805 08:43:33.450006486 15613 tcp_posix.c:168] read: error=null D0805 08:43:33.450039360 15613 tcp_posix.c:173] READ 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 00 04 00 00 00 00 00 00 00 3e 01 04 00 00 00 01 10 0e 63 6f 6e 74 65 6e 74 2d 6c 65 6e 67 74 68 01 30 10 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 10 07 3a 73 74 61 74 75 73 03 32 30 34 '...........>........content-length.0..content-type.application/grpc..:status.204' I0805 08:43:33.450065596 15613 parsing.c:659] HTTP:1:HDR:CLI: content-length: 0 I0805 08:43:33.450083803 15613 parsing.c:659] HTTP:1:HDR:CLI: content-type: application/grpc I0805 08:43:33.450093475 15613 parsing.c:659] HTTP:1:HDR:CLI: :status: 204 D0805 08:43:33.450103340 15613 chttp2_transport.c:675] W:0x138de70 INACTIVE -> REQUESTED[p=0] because parsing_qbuf D0805 08:43:33.450125943 15613 chttp2_transport.c:675] W:0x138de70 REQUESTED[p=0] -> WRITING because start_writing I0805 08:43:33.450172060 15613 connected_channel.c:70] OP[connected:0x1390650]: CLOSE:{"created":"@1470379413.450143313","description":"Received http2 header with status: 204","file":"src/core/lib/transport/transport.c","file_line":215,"grpc_message":"Received http2 header with status: 204","grpc_status":1} D0805 08:43:33.450191302 15613 chttp2_transport.c:675] W:0x138de70 WRITING -> WRITING[p=0] because close_from_api D0805 08:43:33.450204914 15613 tcp_posix.c:405] WRITE 0x138dad0 (peer=ipv4:127.0.0.1:45613): 00 00 00 04 01 00 00 00 00 '.........' I0805 08:43:33.450237331 15613 completion_queue.c:252] grpc_cq_end_op(exec_ctx=0x7ffddfe6c910, cc=0x138bfe0, tag=0x1, error=null, done=0x4151a6, done_arg=0x138c9b8, storage=0x138c9c0) D0805 08:43:33.450250956 15613 chttp2_transport.c:675] W:0x138de70 WRITING[p=0] -> REQUESTED[p=0] because terminate_writing D0805 08:43:33.450263973 15613 chttp2_transport.c:675] W:0x138de70 REQUESTED[p=0] -> INACTIVE because start_writing:nothing_to_write I0805 08:43:33.450278953 15613 completion_queue.c:394] RETURN_EVENT[0x138bfe0]: OP_COMPLETE: tag:0x1 OK D0805 08:43:33.450288122 15613 bad_server_response_test.c:212] Rpc status: 1, details: Received http2 header with status: 204 I0805 08:43:33.450296776 15613 metadata_array.c:47] grpc_metadata_array_destroy(array=0x7ffddfe6ca40) I0805 08:43:33.450303969 15613 metadata_array.c:47] grpc_metadata_array_destroy(array=0x7ffddfe6ca60) I0805 08:43:33.450353881 15613 call.c:720] grpc_call_destroy(c=0x138c950) I0805 08:43:33.450372294 15613 completion_queue.c:541] grpc_completion_queue_shutdown(cc=0x138bfe0) I0805 08:43:33.450383934 15613 completion_queue.c:333] grpc_completion_queue_next(cc=0x138bfe0, deadline=gpr_timespec { tv_sec: 1470379414, tv_nsec: 450380468, clock_type: 1 }, reserved=(nil)) I0805 08:43:33.450393418 15613 completion_queue.c:394] RETURN_EVENT[0x138bfe0]: QUEUE_SHUTDOWN I0805 08:43:33.450400567 15613 completion_queue.c:561] grpc_completion_queue_destroy(cc=0x138bfe0) I0805 08:43:33.450407094 15613 completion_queue.c:541] grpc_completion_queue_shutdown(cc=0x138bfe0) I0805 08:43:33.450414259 15613 channel.c:340] grpc_channel_destroy(channel=0x138c400) D0805 08:43:33.450436781 15613 connectivity_state.c:156] SET: 0x138c548 client_channel: READY --> SHUTDOWN [disconnect] error=0x138d960 {"created":"@1470379413.450422508","description":"Channel Destroyed","file":"src/core/lib/surface/channel.c","file_line":342} D0805 08:43:33.450461540 15613 connectivity_state.c:156] SET: 0x7fc64c000a98 (null): READY --> SHUTDOWN [shutdown] error=0x13933f0 {"created":"@1470379413.450450350","description":"Channel shutdown","file":"src/core/ext/lb_policy/pick_first/pick_first.c","file_line":108} D0805 08:43:33.450469352 15613 connectivity_state.c:183] NOTIFY: 0x138c338 D0805 08:43:33.450477461 15613 connectivity_state.c:106] CONWATCH: 0x13901c0 client_transport: unsubscribe notify=0x7fc64c000a28 D0805 08:43:33.450533270 15613 connectivity_state.c:156] SET: 0x138c548 client_channel: SHUTDOWN --> SHUTDOWN [resolver_gone] error=0x13935c0 {"created":"@1470379413.450493154","description":"Got config after disconnection","file":"src/core/ext/client_config/client_channel.c","file_line":250,"referenced_errors":[{"created":"@1470379413.450446014","description":"Resolver Shutdown","file":"src/core/ext/resolver/dns/native/dns_resolver.c","file_line":115}{"created":"@1470379413.450486882","description":"No load balancing policy","file":"src/core/ext/client_config/client_channel.c","file_line":188}]} D0805 08:43:33.450559605 15613 chttp2_transport.c:459] W:0x138de70 close transport D0805 08:43:33.450567993 15613 chttp2_transport.c:2127] set connectivity_state=4 D0805 08:43:33.450585232 15613 connectivity_state.c:156] SET: 0x13901c0 client_transport: READY --> SHUTDOWN [close_transport] error=0x13935c0 {"created":"@1470379413.450558002","description":"Transport destroyed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":420} D0805 08:43:33.450592647 15613 connectivity_state.c:183] NOTIFY: 0x138de10 D0805 08:43:33.450614222 15613 connectivity_state.c:156] SET: 0x7fc64c000de8 subchannel: READY --> SHUTDOWN [reflect_child] error=0x13935c0 {"created":"@1470379413.450558002","description":"Transport destroyed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":420} D0805 08:43:33.450631123 15613 tcp_posix.c:168] read: error={"created":"@1470379413.450602082","description":"FD shutdown","file":"src/core/lib/iomgr/ev_poll_posix.c","file_line":427} D0805 08:43:33.450642984 15613 chttp2_transport.c:2096] R:0x138de70 -> 0 ws=INACTIVE I0805 08:43:38.450689397 15613 init.c:198] grpc_shutdown(void) I0805 08:43:38.450703544 15613 init.c:198] grpc_shutdown(void)