Grpc: Grpc 1.6.3 timesout request to server

[rgardam]

Should this be an issue in the gRPC issue tracker?

Yes.
This was working on versions prior to 1.6.0. (version 1.4.0)

What version of gRPC and what language are you using?

1.6.0 - 1.6.3

What operating system (Linux, Windows, …) and version?

CentOS Linux release 7.3.1611 (Core)

What runtime / compiler are you using (e.g. python version or version of gcc)

Python 2.7.5

What did you do?

Run a normal request from grpc client to server.
The client is uwsgi flask server.

What did you expect to see?

A request work.

What did you see instead?

The request times out in the uwsgi flask application

GRPC INFO logs from client side

```
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.785650336 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.785682423 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.785692068 19032 channel_create.c:88] grpc_insecure_channel_create(target=grpcservername:50051, args=0x54256d8, reserved=(nil))
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.785789783 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.785797500 19032 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.787211008 19069 channel_connectivity.c:38] grpc_channel_check_connectivity_state(channel=0x5b9bfd0, try_to_connect=0)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.801124817 19069 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.801142528 19069 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.801219843 19069 channel_connectivity.c:209] grpc_channel_watch_connectivity_state(channel=0x5b9bfd0, last_observed_state=0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 1199007, clock_type: 1 }, cq=0x7f24700012e0, tag=0x5b48130)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.801273271 19069 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f24700012e0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 1269594, clock_type: 1 }, reserved=(nil))
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809600184 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809616311 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809621532 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809628984 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809631908 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809635287 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809638214 19032 metadata_array.c:27] grpc_metadata_array_init(array=0x441d1f8)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809641534 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809643910 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809647336 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809650702 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809653014 19032 metadata_array.c:27] grpc_metadata_array_init(array=0x441dae0)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809656946 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809659737 19032 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809671698 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809686428 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809695411 19032 init.c:168] grpc_init(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809728170 19032 call.c:1780] grpc_call_start_batch(call=0x5cb0a98, ops=0x5cb1d40, nops=6, tag=0x5b483d0, reserved=(nil))
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809749593 19032 call.c:1426] ops[0]: SEND_INITIAL_METADATA(nil)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809752783 19032 call.c:1426] ops[1]: SEND_MESSAGE ptr=0x5b8d000
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809755516 19032 call.c:1426] ops[2]: SEND_CLOSE_FROM_CLIENT
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809758346 19032 call.c:1426] ops[3]: RECV_INITIAL_METADATA ptr=0x441d1f8
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809761163 19032 call.c:1426] ops[4]: RECV_MESSAGE ptr=0x3095340
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809765548 19032 call.c:1426] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x441dae0 status=0x5b23840 details=0x5b23848
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809785920 19032 client_channel.c:1383] OP[client-channel:0x5cb1150]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 6e 69 2e 73 65 72 76 69 63 65 73 2e 64 6f 77 6e 6c 6f 61 64 2e 44 6f 77 6e 6c 6f 61 64 2f 67 65 74 5f 75 70 64 61 74 65 '/pathtodef/get_update', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 31 37 2e 36 36 2e 39 31 3a 35 30 30 35 31 'grpcservername:50051'} SEND_MESSAGE:flags=0x00000000:len=38 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809803888 19032 init.c:173] grpc_shutdown(void)
Oct 02 15:36:19 clientaddress.client uwsgi[19028]: I1002 15:36:19.809814328 19032 completion_queue.c:833] grpc_completion_queue_next(cq=0x5cbbea0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 9812690, clock_type: 1 }, reserved=(nil))
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.001595542 19069 completion_queue.c:937] RETURN_EVENT[0x7f24700012e0]: QUEUE_TIMEOUT
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.001630455 19069 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f24700012e0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 201627470, clock_type: 1 }, reserved=(nil))
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.010114929 19032 completion_queue.c:937] RETURN_EVENT[0x5cbbea0]: QUEUE_TIMEOUT
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.010153358 19032 completion_queue.c:833] grpc_completion_queue_next(cq=0x5cbbea0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 210140039, clock_type: 1 }, reserved=(nil))
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.201955906 19069 completion_queue.c:937] RETURN_EVENT[0x7f24700012e0]: QUEUE_TIMEOUT
Oct 02 15:36:20 clientaddress.client uwsgi[19028]: I1002 15:36:20.202005071 19069 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f24700012e0, deadline=gpr_timespec { tv_sec: 1506958580, tv_nsec: 401999481, clock_type: 1 }, reserved=(nil))

GRPC INFO logs grpc server side

Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.058671126 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083603490 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083620113 3956 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083631979 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083638004 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083642428 3956 server.c:1005] grpc_server_create((nil), (nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083647330 3956 init.c:173] grpc_shutdown(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.083654142 3956 server.c:991] grpc_server_register_completion_queue(server=0x1e37780, cq=0x1e3c600, reserved=(nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.085410542 3956 server_chttp2.c:32] grpc_server_add_insecure_http2_port(server=0x1e37780, addr=grpcservername:50051)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.085929933 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.085938473 3956 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=1)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.085944995 3956 server.c:991] grpc_server_register_completion_queue(server=0x1e37780, cq=0x1e5a420, reserved=(nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.085948707 3956 server.c:1087] grpc_server_start(server=0x1e37780)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087010139 3956 completion_queue.c:833] grpc_completion_queue_next(cq=0x1e5a420, deadline=gpr_timespec { tv_sec: 1506959317, tv_nsec: 87005284, clock_type: 1 }, reserved=(nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087028753 3956 completion_queue.c:937] RETURN_EVENT[0x1e5a420]: QUEUE_TIMEOUT
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087044165 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087047774 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087051441 3956 call_details.c:29] grpc_call_details_init(cd=0x19289a0)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087054650 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087068456 3956 metadata_array.c:27] grpc_metadata_array_init(array=0x19d02e8)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087072358 3956 init.c:168] grpc_init(void)
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.087076793 3956 server.c:1437] grpc_server_request_call(server=0x1e37780, call=0x19a3b20, details=0x19289a0, initial_metadata=0x19d02e8, cq_bound_to_call=0x1e3c600, cq_for_notification=0x1e3c600, tag=0x21978a0)
Oct 02 15:48:37 grpcService service.py[3956]: [2017-10-02Z15:48:37 INFO __main__ serve 227] Service listening on grpcservername:50051
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.090938108 3966 completion_queue.c:833] grpc_completion_queue_next(cq=0x1e3c600, deadline=gpr_timespec { tv_sec: 1506959317, tv_nsec: 290934284, clock_type: 1 }, reserved=(nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.291272810 3966 completion_queue.c:937] RETURN_EVENT[0x1e3c600]: QUEUE_TIMEOUT
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.291308136 3966 completion_queue.c:833] grpc_completion_queue_next(cq=0x1e3c600, deadline=gpr_timespec { tv_sec: 1506959317, tv_nsec: 491304864, clock_type: 1 }, reserved=(nil))
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.491621396 3966 completion_queue.c:937] RETURN_EVENT[0x1e3c600]: QUEUE_TIMEOUT
Oct 02 15:48:37 grpcService service.py[3956]: I1002 15:48:37.491652287 3966 completion_queue.c:833] grpc_completion_queue_next(cq=0x1e3c600, deadline=gpr_timespec { tv_sec: 1506959317, tv_nsec: 691649170, clock_type: 1 }, reserved=(nil))
```

[kpayson64]

Is there any chance you are using multiprocessing/fork?

fork() was never supported with gRPC, but certain use cases were working pre-1.6. Changes to the c internals in 1.6 caused these to stop working, #12455

[rgardam]

Hi @kpayson64 Thanks for the heads up.

Turns out this was exactly what was happening.

Uwsgi's default behaviour is to fork.

http://uwsgi-docs.readthedocs.io/en/latest/articles/TheArtOfGracefulReloading.html#preforking-vs-lazy-apps-vs-lazy

by setting

lazy-apps = true

in our uwsgi config we were able to avoid this bug at the cost of memory.

I imagine this is a pretty common use case for application servers.
Will this be possible in 1.7?

[vjpai]

Forking is possible in 1.7 . Marking to-close.