Hello folks, I'm currently experimenting with the built in load balancer support, specifically:
https://github.com/grpc/proposal/blob/ce4fe27b88eec315ec0d5fe1d40bb795c0ee94b1/A5-grpclb-in-dns.md I'm encountering an error and before creating a bug report I'd like to make sure I've not missed anything. We've setup the DNS according to the doc: $> dig +noall +answer SRV _grpclb._tcp.server._tcp.internal.example.com _grpclb._tcp.server._tcp.internal.example.com. 120 IN SRV 0 0 2379 nodes.internal.example.com. $> dig +noall +answer A nodes.internal.example.com nodes.internal.example.com. 120 IN A 10.10.44.90 nodes.internal.example.com. 120 IN A 10.10.19.222 nodes.internal.example.com. 120 IN A 10.10.3.170 Using a Python client (3.10, grpcio 1.51.1): # [...] channel = grpc.secure_channel( "server._tcp.internal.example.com", credentials=grpc.ssl_channel_credentials( ca_cert_file, cert_key_file, cert_cert_file, ), options=( ("grpc.dns_enable_srv_queries", 1), ("grpc.lb_policy_name", "round_robin"), ), ) server = rpc.ServerStub(channel) req = rpcpb.StatusRequest() server.Status(rep) When I execute this code, I get the following exception: Traceback (most recent call last): File "/tmp/test.py", line 57, in <module> server.Status(streq) File "/....../grpc/_channel.py", line 946, in __call__ return _end_unary_response_blocking(state, call, False, None) File "/....../grpc/_channel.py", line 849, in _end_unary_response_blocking raise _InactiveRpcError(state) grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with: status = StatusCode.UNAVAILABLE details = "empty address list: " debug_error_string = "UNKNOWN:empty address list: {created_time:"2023-01-26T17:10:23.423558027+01:00", grpc_status:14}" When I enable the gRPC logs, I can see that ares properly resolves the addresses: D0126 17:10:23.355144647 1897428 grpc_ares_wrapper.cc:726] (c-ares resolver) request:0x888c20 on_srv_query_done_locked name=_grpclb._tcp.server._tcp.internal.example.com ARES_SUCCESS D0126 17:10:23.355170775 1897428 grpc_ares_wrapper.cc:731] (c-ares resolver) request:0x888c20 ares_parse_srv_reply: 0 D0126 17:10:23.355175243 1897428 grpc_ares_wrapper.cc:625] (c-ares resolver) request:0x888c20 create_hostbyname_request_locked host:nodes.internal.example.com port:19209 is_balancer:1 qtype:AAAA D0126 17:10:23.355270526 1897428 grpc_ares_wrapper.cc:625] (c-ares resolver) request:0x888c20 create_hostbyname_request_locked host:nodes.internal.example.com port:19209 is_balancer:1 qtype:A D0126 17:10:23.355363205 1897428 grpc_ares_wrapper.cc:191] (c-ares resolver) request:0x888c20 Ref ev_driver 0x888d00 D0126 17:10:23.355368326 1897428 grpc_ares_wrapper.cc:439] (c-ares resolver) request:0x888c20 notify read on: c-ares fd: 6 D0126 17:10:23.355388528 1897428 grpc_ares_wrapper.cc:202] (c-ares resolver) request:0x888c20 Unref ev_driver 0x888d00 D0126 17:10:23.422973484 1897428 grpc_ares_wrapper.cc:364] (c-ares resolver) request:0x888c20 readable on c-ares fd: 6 D0126 17:10:23.423048620 1897428 grpc_ares_wrapper.cc:710] (c-ares resolver) request:0x888c20 on_hostbyname_done_locked: C-ares status is not ARES_SUCCESS qtype=AAAA name=nodes.internal.example.com is_balancer=1: DNS server returned answer with no data D0126 17:10:23.423217106 1897428 grpc_ares_wrapper.cc:655] (c-ares resolver) request:0x888c20 on_hostbyname_done_locked qtype=A host=nodes.internal.example.com ARES_SUCCESS D0126 17:10:23.423241972 1897428 grpc_ares_wrapper.cc:698] (c-ares resolver) request:0x888c20 c-ares resolver gets a AF_INET result: addr: 10.10.44.90 port: 2379 D0126 17:10:23.423245904 1897428 grpc_ares_wrapper.cc:698] (c-ares resolver) request:0x888c20 c-ares resolver gets a AF_INET result: addr: 10.10.3.170 port: 2379 D0126 17:10:23.423249513 1897428 grpc_ares_wrapper.cc:698] (c-ares resolver) request:0x888c20 c-ares resolver gets a AF_INET result: addr: 10.10.19.222 port: 2379 D0126 17:10:23.423252890 1897428 grpc_ares_wrapper.cc:202] (c-ares resolver) request:0x888c20 Unref ev_driver 0x888d00 D0126 17:10:23.423261751 1897428 grpc_ares_wrapper.cc:216] (c-ares resolver) request:0x888c20 delete fd: c-ares fd: 6 D0126 17:10:23.423266242 1897428 grpc_ares_wrapper.cc:202] (c-ares resolver) request:0x888c20 Unref ev_driver 0x888d00 D0126 17:10:23.423270617 1897428 grpc_ares_wrapper.cc:293] (c-ares resolver) request:0x888c20 ev_driver=0x888d00 on_timeout_locked. driver->shutting_down=1. err=CANCELLED D0126 17:10:23.423272866 1897428 grpc_ares_wrapper.cc:202] (c-ares resolver) request:0x888c20 Unref ev_driver 0x888d00 D0126 17:10:23.423275996 1897428 grpc_ares_wrapper.cc:318] (c-ares resolver) request:0x888c20 ev_driver=0x888d00 on_ares_backup_poll_alarm_locked. driver->shutting_down=1. err=CANCELLED D0126 17:10:23.423278521 1897428 grpc_ares_wrapper.cc:202] (c-ares resolver) request:0x888c20 Unref ev_driver 0x888d00 D0126 17:10:23.423303740 1897428 grpc_ares_wrapper.cc:205] (c-ares resolver) request:0x888c20 destroy ev_driver 0x888d00 I0126 17:10:23.423316475 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: input[0]=10.10.44.90:2379 I0126 17:10:23.423320669 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: input[1]=10.10.3.170:2379 I0126 17:10:23.423323482 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: input[2]=10.10.19.222:2379 I0126 17:10:23.423375716 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: output[0]=10.10.44.90:2379 I0126 17:10:23.423378492 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: output[1]=10.10.3.170:2379 I0126 17:10:23.423380187 1897428 grpc_ares_wrapper.cc:552] (c-ares resolver) request:0x888c20 c-ares address sorting: output[2]=10.10.19.222:2379 D0126 17:10:23.423382614 1897428 dns_resolver_ares.cc:396] (c-ares resolver) resolver:0x69ed30 OnResolved() proceeding I0126 17:10:23.423409387 1897428 polling_resolver.cc:137] [polling resolver 0x8d7270] request complete I0126 17:10:23.423413325 1897428 polling_resolver.cc:142] [polling resolver 0x8d7270] returning result: addresses=<0 addresses>, service_config=<null> As we can see in the last line we return 0 addresses instead of the three. When checking the code, dns_resolver_ares.cc, I wonder whether the code handling the `balancer_addresses_` is missing: - We should have only balancer addresses so we init `result.addresses` with an empty list: `ServerAddressList`: - https://github.com/grpc/grpc/blob/f99b8b5bc4a89d37f86bf063999ec22e44312663/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc#L405 - Further down, after any config handling if present, we can see that addresses is not written, but instead `result.arg` is set with the addresses we resolved and put under the `grpc.grpclb_balancer_addresses` key whereas the policy expect it in the addresses field - https://github.com/grpc/grpc/blob/f99b8b5bc4a89d37f86bf063999ec22e44312663/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc#L428 - https://github.com/grpc/grpc/blob/50fbe51238e8932b180e5e18eaa9ab87d26ecc10/src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb_balancer_addresses.cc#L82 - https://github.com/grpc/grpc/blob/v1.51.1/src/core/ext/filters/client_channel/lb_policy/round_robin/round_robin.cc#L274 Here are the next logs following the polling_resolver: I0126 17:10:23.423448035 1897428 round_robin.cc:239] [RR 0x8da3f0] Created I0126 17:10:23.423454769 1897428 round_robin.cc:271] [RR 0x8da3f0] received update with 0 addresses I0126 17:10:23.423458411 1897428 subchannel_list.h:367] [RoundRobinSubchannelList 0x8da3f0] Creating subchannel list 0x8c3f40 for 0 subchannels I0126 17:10:23.423471480 1897428 channel_stack.cc:114] CHANNEL_STACK: init DynamicFilters I0126 17:10:23.423474992 1897428 channel_stack.cc:116] CHANNEL_STACK: filter retry_filter I0126 17:10:23.423491810 1897428 client_channel.cc:2169] chand=0x908060 calld=0x950880: applying service config to call I0126 17:10:23.423495972 1897428 client_channel.cc:2140] chand=0x908060 calld=0x950880: removing from resolver queued picks list I0126 17:10:23.423501202 1897428 polling_resolver.cc:172] [polling resolver 0x8d7270] result status from channel: UNAVAILABLE: empty address list: I0126 17:10:23.423505125 1897428 polling_resolver.cc:197] [polling resolver 0x8d7270] retrying in 1000 ms I0126 17:10:23.423511785 1897428 client_channel.cc:2372] chand=0x908060 calld=0x950880: creating dynamic call stack on channel_stack=0x90dc20 I0126 17:10:23.423519385 1897428 client_channel.cc:2068] chand=0x908060 calld=0x950880: starting 1 pending batches on dynamic_call=0x9512b0 Is there anything I'm missing? Thanks a lot, Thomas Sanchez -- You received this message because you are subscribed to the Google Groups "grpc.io" group. To unsubscribe from this group and stop receiving emails from it, send an email to grpc-io+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/a99b894b-565b-4c71-b8c6-379175b04acdn%40googlegroups.com.
