gRPC Python quickstart/helloworld (greeter_client.py) is hanging before printing "Greeter client received: ..."

Viewed 631

Today I wanted to start implementing a gRPC client and server for a program I wrote in Python. I have followed the tutorial found here: https://grpc.io/docs/languages/python/quickstart/.

By follow I mean I have follow directions exactly, typing each command exactly as written. First installing all requirements (in a conda environemnt) then running the greeter_server.py and greeter_client.py. Techinically the program works, but the client program hangs for about 30-40 seconds on my system before responding with the simple greeting "Greeter client received: Hello, you!".

So I decided to try the Go version of the quick start tutorial found here: https://grpc.io/docs/languages/go/quickstart/. Again following all instructions exactly as writtten and building and starting both the go server and go client, the client program responds in less than a second with "2020/08/27 12:48:24 Greeting: Hello world".

The go version is behaving in exactly the way I would expect. Yet the Python version takes almost a minute to respond with a simple message. Does anyone have any idea what is going on?

Thanks in advance.

Edit 1) - I will supplement the original question with some testing I have just done. I apologize for the lack of in the original. So, I have been testing on different machines. On my desktop which is an Ubuntu 20 machine the issue is present. I can simply pop open a terminal, create a new conda environment (I have used Python 3.8 for these tests). I perform the Quick Start tutorial. The Python version is NOT working as expected (it takes far too long to convince me everythign is working properly). I perform the Quick Start in Go and every thing runs fine.

I tested this tutorial on my 2011 mac book air, starting a terminal, creating a new conda environment (3.8) and the Python version of gRPC Quick Start is working fine (as in there is no humanly noticable difference) compared to the Go version.

So I am wondering if there are any gRPC experts who would have a suggestion as to why this happens. I have restarted my machine and tested again, still the problem persists on my Ubuntu linux machine.

Edit 2) - I just ran a simiar test on an Ubuntu 20 cloud VM and everything works as expected (no difference between Python and Go versions). I tried a seprate random "echo" gRPC Python tutorial I found online (unrelated to the gRPC Quick Start tutorial) and the issue persists on my local. So I believe the issue can be isolated to my environment. I am lost.

Edit 3) - I ran the client code through a debugger and added break points.

from __future__ import print_function
import logging

import grpc

import helloworld_pb2
import helloworld_pb2_grpc


def run():
    # NOTE(gRPC Python Team): .close() is possible on a channel and should be
    # used in circumstances in which the with statement does not fit the needs
    # of the code.
    with grpc.insecure_channel('localhost:50051') as channel: # added break
        stub = helloworld_pb2_grpc.GreeterStub(channel) # added break
        response = stub.SayHello(helloworld_pb2.HelloRequest(name='you')) # added break - HANGS ASSINING `response` OBJECT
    print("Greeter client received: " + response.message) # added break


if __name__ == '__main__':
    logging.basicConfig()
    run()

It is is hanging just before the print statement, within the with block. On my mac I set the same break points and the debugger instantly assigns the reponse object to memory and prints. On my Ubuntu machine the debugger hangs trying to assign the response = stub.SayHello(helloworld_pb2.HelloRequest(name='you')) variable. I have noticed the use of Cython which may be a clue.

If I interupt the greeter_client.py process I get the following trace:

  File "greeter_client.py", line 37, in <module>
    run()
  File "greeter_client.py", line 31, in run
    response = stub.SayHello(helloworld_pb2.HelloRequest(name='you'))
  File "/home/james/.local/lib/python3.8/site-packages/grpc/_channel.py", line 824, in __call__
    state, call, = self._blocking(request, timeout, metadata, credentials,
  File "/home/james/.local/lib/python3.8/site-packages/grpc/_channel.py", line 813, in _blocking
    event = call.next_event()
  File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 338, in grpc._cython.cygrpc.SegregatedCall.next_event
  File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 169, in grpc._cython.cygrpc._next_call_event
  File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 163, in grpc._cython.cygrpc._next_call_event
  File "src/python/grpcio/grpc/_cython/_cygrpc/completion_queue.pyx.pxi", line 63, in grpc._cython.cygrpc._latent_event
  File "src/python/grpcio/grpc/_cython/_cygrpc/completion_queue.pyx.pxi", line 42, in grpc._cython.cygrpc._next
KeyboardInterrupt

Edit 4) - One of the commenters had a good suggestion to test the python client and go server combination (gRPC allows this with zero effort, go gRPC). I performed the test and the Python client is still as slow or slower in responding. The go client - go server combination still quick. I believe this narrows it down to an issue on the Python client side. Thank you @DazWilkin. For completeness, the Go client - Python server works as expected in < 1 second.

Edit 5) - Last night I completely reinstalled a minimal version of Ubuntu 20.04. On a fresh system there is still about a 45 second delay for the simple greeter_client.py to respond. :(

1 Answers

This could be a common issue with all wrapper languages (Python, Ruby, PHP, C#, Node). The direct cause is that the C-Ares name resolver failed to resolve the IPv6 address of localhost. It can be circumvented by specifying an environment variable GRPC_DNS_RESOLVER=native, which changes the default name resolver.

Here is the hang section from the log provided by James:

D0831 13:09:27.577593604    6445 dns_resolver_ares.cc:184]   (c-ares resolver) resolver:0x55eaa9dbd8a0 AresDnsResolver::StartLocked() is called.
D0831 13:09:27.577596674    6445 grpc_ares_wrapper.cc:645]   (c-ares resolver) request:0x55eaa9d99b80 c-ares grpc_dns_lookup_ares_locked_impl name=localhost:50051, default_port=https
D0831 13:09:27.577653493    6445 grpc_ares_ev_driver.cc:158] (c-ares resolver) request:0x55eaa9d99b80 grpc_ares_ev_driver_create_locked
D0831 13:09:27.577679913    6445 grpc_ares_wrapper.cc:200]   (c-ares resolver) request:0x55eaa9d99b80 create_hostbyname_request_locked host:localhost port:33731 is_balancer:0 qtype:AAAA
D0831 13:09:27.577725082    6445 grpc_ares_wrapper.cc:200]   (c-ares resolver) request:0x55eaa9d99b80 create_hostbyname_request_locked host:localhost port:33731 is_balancer:0 qtype:A
D0831 13:09:27.577736032    6445 grpc_ares_wrapper.cc:227]   (c-ares resolver) request:0x55eaa9d99b80 on_hostbyname_done_locked qtype=A host=localhost ARES_SUCCESS
D0831 13:09:27.577740632    6445 grpc_ares_wrapper.cc:273]   (c-ares resolver) request:0x55eaa9d99b80 c-ares resolver gets a AF_INET result: 
  addr: 127.0.0.1
  port: 50051

D0831 13:09:27.577745522    6445 grpc_ares_ev_driver.cc:392] (c-ares resolver) request:0x55eaa9d99b80 new fd: c-ares fd: 10
D0831 13:09:27.577748092    6445 grpc_ares_ev_driver.cc:98]  (c-ares resolver) request:0x55eaa9d99b80 Ref ev_driver 0x55eaa9cfd900
D0831 13:09:27.577750552    6445 grpc_ares_ev_driver.cc:406] (c-ares resolver) request:0x55eaa9d99b80 notify read on: c-ares fd: 10
D0831 13:09:27.577753342    6445 grpc_ares_ev_driver.cc:463] (c-ares resolver) request:0x55eaa9d99b80 ev_driver=0x55eaa9cfd900 grpc_ares_ev_driver_start_locked. timeout in 120000 ms
D0831 13:09:27.577755682    6445 grpc_ares_ev_driver.cc:98]  (c-ares resolver) request:0x55eaa9d99b80 Ref ev_driver 0x55eaa9cfd900
D0831 13:09:27.577763612    6445 grpc_ares_ev_driver.cc:227] (c-ares resolver) request:0x55eaa9d99b80 ev_driver=0x55eaa9cfd900. next ares process poll time in 1000 ms
D0831 13:09:27.577765852    6445 grpc_ares_ev_driver.cc:98]  (c-ares resolver) request:0x55eaa9d99b80 Ref ev_driver 0x55eaa9cfd900
D0831 13:09:27.577773282    6445 dns_resolver_ares.cc:448]   (c-ares resolver) resolver:0x55eaa9dbd8a0 Started resolving. pending_request_:0x55eaa9d99b80

The tracking issue for this bug located in grpc#24018. For anyone still blocked by this issue, feel free to comment on the thread so it can get more attention.

Related