Go client context deadline exceeded

dapengzhang0 commented 3 years ago

Expected Behavior

user@grpc-wallet-client:~/traffic-director-grpc-examples/go/wallet_client$ ./wallet_client price --stats_server="xds:///stats.grpcwallet.io" --watch --user=Bob
2021/08/26 17:57:13 server host: grpcwallet-stats-mig-us-central1-gljr
2021/08/26 17:57:13 grpc-coin price: 9110.
2021/08/26 17:57:14 grpc-coin price: 9018.

Actual Behavior

user@grpc-wallet-client:~/traffic-director-grpc-examples/go/wallet_client$ ./wallet_client price --stats_server="xds:///stats.grpcwallet.io" --watch --user=Bob
021/08/26 17:39:48 xDS credentials in use: false
2021/08/26 17:39:58 Failed to connect to the Wallet server: context deadline exceeded

Steps to Reproduce the Problem

Follow the UG example and run the command.

Specifications

Version: master branch (It works if the client repo is checkout to v1.0.x branch)

dapengzhang0 commented 3 years ago

@menghanl @easwars Could you please take a look at the issue?

menghanl commented 3 years ago

What's in the log? https://github.com/grpc/grpc-go#how-to-turn-on-logging

dapengzhang0 commented 3 years ago

What's in the log? https://github.com/grpc/grpc-go#how-to-turn-on-logging

2021/08/26 20:52:03 xDS credentials in use: false
INFO: 2021/08/26 20:52:03 [core] Channel Created
INFO: 2021/08/26 20:52:03 [core] parsed scheme: ""
INFO: 2021/08/26 20:52:03 [core] scheme "" not registered, fallback to default scheme
INFO: 2021/08/26 20:52:03 [core] ccResolverWrapper: sending update to cc: {[{localhost:18881  <nil> 0 <nil>}] <nil> <nil>}
INFO: 2021/08/26 20:52:03 [core] Resolver state updated: {Addresses:[{Addr:localhost:18881 ServerName: Attributes:<nil> Type:0 Metadata:<nil>}] ServiceConfig:<nil> Attributes:<nil>} (resolver returned new addresses)
INFO: 2021/08/26 20:52:03 [core] ClientConn switching balancer to "pick_first"
INFO: 2021/08/26 20:52:03 [core] Channel switches to new LB policy "pick_first"
INFO: 2021/08/26 20:52:03 [core] Subchannel Created
INFO: 2021/08/26 20:52:03 [core] Subchannel(id:2) created
INFO: 2021/08/26 20:52:03 [core] Subchannel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:03 [core] Subchannel picks a new address "localhost:18881" to connect
INFO: 2021/08/26 20:52:03 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {CONNECTING <nil>}
INFO: 2021/08/26 20:52:03 [core] Channel Connectivity change to CONNECTING
WARNING: 2021/08/26 20:52:03 [core] grpc: addrConn.createTransport failed to connect to {localhost:18881 localhost:18881 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused". Reconnecting...
INFO: 2021/08/26 20:52:03 [core] Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:03 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused"}
INFO: 2021/08/26 20:52:03 [core] Channel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:04 [core] Subchannel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:04 [core] Subchannel picks a new address "localhost:18881" to connect
INFO: 2021/08/26 20:52:04 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {CONNECTING <nil>}
INFO: 2021/08/26 20:52:04 [core] Channel Connectivity change to CONNECTING
WARNING: 2021/08/26 20:52:04 [core] grpc: addrConn.createTransport failed to connect to {localhost:18881 localhost:18881 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused". Reconnecting...
INFO: 2021/08/26 20:52:04 [core] Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:04 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused"}
INFO: 2021/08/26 20:52:04 [core] Channel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:06 [core] Subchannel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:06 [core] Subchannel picks a new address "localhost:18881" to connect
INFO: 2021/08/26 20:52:06 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {CONNECTING <nil>}
INFO: 2021/08/26 20:52:06 [core] Channel Connectivity change to CONNECTING
WARNING: 2021/08/26 20:52:06 [core] grpc: addrConn.createTransport failed to connect to {localhost:18881 localhost:18881 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused". Reconnecting...
INFO: 2021/08/26 20:52:06 [core] Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:06 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused"}
INFO: 2021/08/26 20:52:06 [core] Channel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:08 [core] Subchannel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:08 [core] Subchannel picks a new address "localhost:18881" to connect
INFO: 2021/08/26 20:52:08 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {CONNECTING <nil>}
INFO: 2021/08/26 20:52:08 [core] Channel Connectivity change to CONNECTING
WARNING: 2021/08/26 20:52:08 [core] grpc: addrConn.createTransport failed to connect to {localhost:18881 localhost:18881 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused". Reconnecting...
INFO: 2021/08/26 20:52:08 [core] Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:08 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused"}
INFO: 2021/08/26 20:52:08 [core] Channel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:12 [core] Subchannel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:12 [core] Subchannel picks a new address "localhost:18881" to connect
WARNING: 2021/08/26 20:52:12 [core] grpc: addrConn.createTransport failed to connect to {localhost:18881 localhost:18881 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused". Reconnecting...
INFO: 2021/08/26 20:52:12 [core] Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:12 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {CONNECTING <nil>}
INFO: 2021/08/26 20:52:12 [core] Channel Connectivity change to CONNECTING
INFO: 2021/08/26 20:52:12 [core] pickfirstBalancer: UpdateSubConnState: 0xc000070b20, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing dial tcp [::1]:18881: connect: connection refused"}
INFO: 2021/08/26 20:52:12 [core] Channel Connectivity change to TRANSIENT_FAILURE
INFO: 2021/08/26 20:52:13 [core] Channel Connectivity change to SHUTDOWN
INFO: 2021/08/26 20:52:13 [core] Subchannel Connectivity change to SHUTDOWN
INFO: 2021/08/26 20:52:13 [core] Subchannel Deleted
INFO: 2021/08/26 20:52:13 [core] Subchanel(id:2) deleted
INFO: 2021/08/26 20:52:13 [core] Channel Deleted
INFO: 2021/08/26 20:52:13 [channelz] attempt to delete child with id 2 from a parent (id=1) that doesn't currently exist
INFO: 2021/08/26 20:52:13 [channelz] attempt to delete child with id 2 from a parent (id=1) that doesn't currently exist
2021/08/26 20:52:13 Failed to connect to the Wallet server: context deadline exceeded

How to turn on xds client log?

dapengzhang0 commented 3 years ago

Is it using the default port 18881 and dns resolver? So xds client is not used.

INFO: 2021/08/26 20:52:03 [core] parsed scheme: ""
INFO: 2021/08/26 20:52:03 [core] scheme "" not registered, fallback to default scheme

menghanl commented 3 years ago

Yes, and it's connecting to localhost:18881. Seems it didn't get the flags at all?

menghanl commented 3 years ago

~Can you try this https://github.com/GoogleCloudPlatform/traffic-director-grpc-examples/pull/74?~

Actually, this doesn't look right. Parse() is called in parseArguments()

dapengzhang0 commented 3 years ago

I think the problem comes from this change: https://github.com/GoogleCloudPlatform/traffic-director-grpc-examples/commit/27d66b0aa840f75429a21100295bb4c658c2a569#diff-f1b9f1cd035de81ff11626c152d6ba7cd0edd286f6ec98fa541f022a9ce42e09R258

It's always trying to connect wallet server after the change, even for price command.

menghanl commented 3 years ago

Yes, this should fix it: https://github.com/GoogleCloudPlatform/traffic-director-grpc-examples/pull/75

dapengzhang0 commented 3 years ago

Test passed after fix #75.

GoogleCloudPlatform / traffic-director-grpc-examples