grpc-go Wait-for-Readyを使いECS rolling updateでダウンタイム発生しにくくなることを検証

ECSサービスへgRPCリクエスト中にECSサービスを更新するとダウンタイムが発生する
Wait-for-Readyを使うことでダウンタイムが発生しにくくなることを検証する

## 検証する環境と方法
### aws構成
クライアントはAWS Cloud MapのDNSを使用してサーバー側ECSタスクを名前解決する
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/481044/51280911-16b7-6702-116b-fe5fe2030fa9.png)
以下各サービスの設定値
- Cloud Map 名前空間
    - インスタンスの検出: "API呼び出しとVPCのDNSクエリ"
    - TTL: 15秒
- ECSサービス
    - 最小実行タスク: 100%
    - 最大実行タスク: 200%
    - サービス検出
        - "Amazon ECS タスク状態の伝達を有効にする": 有効
        - DNSレコード
            - DNSレコードタイプ: A
            - TTL: 15秒
- ECSタスク定義 / サーバー
    - 特にコンテナヘルスチェック設定はしていない
- ECSタスク定義 / クライアント
    - 特にコンテナヘルスチェック設定はしていない
    - 環境変数
        - GRPC_GO_LOG_VERBOSITY_LEVEL: 99
        - GRPC_GO_LOG_SEVERITY_LEVEL: info


### アプリケーション
- 使用する言語、ライブラリ
    - Go 1.22
    - google.golang.org/grpc v1.63.2
- サーバーコード
    - リクエストされた文字列をそのまま返す
    - graceful shutdownを入れている
    ```go:Go
    package main
    
    import (
        "context"
        "log"
        "net"
        "os"
        "os/signal"
        "syscall"
        "time"
    
        "google.golang.org/grpc"
    
        pb "google.golang.org/grpc/examples/features/proto/echo"
    )
    
    type ecServer struct {
        pb.UnimplementedEchoServer
    }
    
    func (s *ecServer) UnaryEcho(_ context.Context, req *pb.EchoRequest) (*pb.EchoResponse, error) {
        time.Sleep(1 * time.Second)
        return &pb.EchoResponse{Message: req.Message}, nil
    }
    
    func main() {
        lis, err := net.Listen("tcp", ":50051")
        if err != nil {
            log.Fatalf("failed to listen: %v", err)
        }
        s := grpc.NewServer()
        pb.RegisterEchoServer(s, &ecServer{})
    
        ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, os.Kill, syscall.SIGTERM)
        defer stop()
    
        log.Println("serving on :50051")
        go func() {
            if err := s.Serve(lis); err != nil {
                stop()
                log.Fatalf("failed to serve: %v", err)
            }
        }()
    
        <-ctx.Done()
        log.Println("shutting down")
        s.GracefulStop()
    }
    ```

- クライアントコード
    - サーバーに"hello"をリクエストしレスポンスを出力する
    - これを一定数繰り返す
    ```go:Go
    package main
    
    import (
        "context"
        "log"
        "os"
        "time"
    
        "google.golang.org/grpc"
        "google.golang.org/grpc/credentials/insecure"
        ecpb "google.golang.org/grpc/examples/features/proto/echo"
    )
    
    func main() {
        conn, err := grpc.NewClient(
            "server.grpc.local:50051", // Cloud MapのDNS
            grpc.WithTransportCredentials(insecure.NewCredentials()),
            grpc.WithDefaultCallOptions(
                grpc.WaitForReady(true), // Wait-for-Ready設定
            ),
        )
        if err != nil {
            log.Fatalf("did not connect: %v", err)
        }
        defer conn.Close()
    
        hwc := ecpb.NewEchoClient(conn)
        for i := 0; i < 300; i++ {
            ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
            defer cancel()
            r, err := hwc.UnaryEcho(ctx, &ecpb.EchoRequest{Message: "hello"})
            if err != nil {
                log.Printf("could not invoke: %v\n", err)
                time.Sleep(1 * time.Second)
                continue
            }
            log.Println(r.Message)
        }
    }
    ```

### 検証方法
クライアントをECSタスクで起動し、gRPCリクエスト中にサーバー側ECSサービスを強制更新する
クライアント側ECSタスクのログを確認する

## Wait-for-Readyなしのログ
- 新しい接続(10.0.27.158)を見つけるまで"could not invoke: "エラーが出続けている

```
...
2024/04/20 13:39:35 hello
2024/04/20 13:39:36 hello
2024/04/20 13:39:37 hello
"2024/04/20 13:39:37 INFO: [transport] [client-transport 0x40000eb208] Closing: connection error: desc = ""error reading from server: EOF"""
2024/04/20 13:39:37 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
"2024/04/20 13:39:37 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:<nil>}"
2024/04/20 13:39:37 INFO: [transport] [client-transport 0x40000eb208] loopyWriter exiting with error: transport closed by client
2024/04/20 13:39:37 INFO: [core] [Channel #1]Channel Connectivity change to IDLE
2024/04/20 13:39:37 could not invoke: rpc error: code = Unavailable desc = error reading from server: EOF
2024/04/20 13:39:38 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:38 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:38 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
2024/04/20 13:39:38 INFO: [core] [Channel #1]Channel Connectivity change to CONNECTING
"2024/04/20 13:39:38 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:38 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:38 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:38 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
2024/04/20 13:39:38 INFO: [core] [Channel #1]Channel Connectivity change to TRANSIENT_FAILURE
"2024/04/20 13:39:38 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:39 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
"2024/04/20 13:39:39 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
2024/04/20 13:39:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:39 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:39:39 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:39 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:39 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
"2024/04/20 13:39:40 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:41 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:41 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
2024/04/20 13:39:41 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:41 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:41 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:39:41 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:41 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:41 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:41 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
"2024/04/20 13:39:41 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:42 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:43 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:44 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:44 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
2024/04/20 13:39:44 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:44 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:44 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:39:44 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:44 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:44 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:44 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
"2024/04/20 13:39:44 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:45 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:46 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:47 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:47 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
2024/04/20 13:39:47 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:47 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:47 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:39:47 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:47 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:47 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:47 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
"2024/04/20 13:39:47 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:48 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:49 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:50 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:51 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:52 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:53 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:53 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused""}"
2024/04/20 13:39:53 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:39:53 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.19.136:50051"" to connect"
"2024/04/20 13:39:53 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:39:53 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:54 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:55 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:56 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:57 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:58 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:39:59 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:00 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:01 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:02 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:03 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:04 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:05 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
"2024/04/20 13:40:06 could not invoke: rpc error: code = Unavailable desc = connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: connect: connection refused"""
2024/04/20 13:40:07 INFO: [core] [Channel #1]Resolver state updated: {
"  ""Addresses"": ["
    {
"      ""Addr"": ""10.0.27.158:50051"","
"      ""ServerName"": """","
"      ""Attributes"": null,"
"      ""BalancerAttributes"": null,"
"      ""Metadata"": null"
    }
"  ],"
"  ""Endpoints"": ["
    {
"      ""Addresses"": ["
        {
"          ""Addr"": ""10.0.27.158:50051"","
"          ""ServerName"": """","
"          ""Attributes"": null,"
"          ""BalancerAttributes"": null,"
"          ""Metadata"": null"
        }
"      ],"
"      ""Attributes"": null"
    }
"  ],"
"  ""ServiceConfig"": null,"
"  ""Attributes"": null"
} ()
2024/04/20 13:40:07 INFO: [core] [pick-first-lb 0x400013b0e0] Received new config {
"  ""shuffleAddressList"": false"
"}, resolver state {"
"  ""Addresses"": ["
    {
"      ""Addr"": ""10.0.27.158:50051"","
"      ""ServerName"": """","
"      ""Attributes"": null,"
"      ""BalancerAttributes"": null,"
"      ""Metadata"": null"
    }
"  ],"
"  ""Endpoints"": ["
    {
"      ""Addresses"": ["
        {
"          ""Addr"": ""10.0.27.158:50051"","
"          ""ServerName"": """","
"          ""Attributes"": null,"
"          ""BalancerAttributes"": null,"
"          ""Metadata"": null"
        }
"      ],"
"      ""Attributes"": null"
    }
"  ],"
"  ""ServiceConfig"": null,"
"  ""Attributes"": null"
}
2024/04/20 13:40:07 INFO: [core] [Channel #1 SubChannel #2]addrConn: updateAddrs curAddr: {
"  ""Addr"": ""10.0.19.136:50051"","
"  ""ServerName"": ""server.grpc.local:50051"","
"  ""Attributes"": null,"
"  ""BalancerAttributes"": null,"
"  ""Metadata"": null"
"}, addrs: ["
  {
"    ""Addr"": ""10.0.27.158:50051"","
"    ""ServerName"": """","
"    ""Attributes"": null,"
"    ""BalancerAttributes"": null,"
"    ""Metadata"": null"
  }
]
"2024/04/20 13:40:07 INFO: [core] Creating new client transport to ""{Addr: \""10.0.19.136:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: operation was canceled"""
"2024/04/20 13:40:07 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.19.136:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.19.136:50051: operation was canceled"""
"2024/04/20 13:40:07 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
2024/04/20 13:40:07 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to READY
"2024/04/20 13:40:07 INFO: [core] [pick-first-lb 0x400013b0e0] Received SubConn state update: 0x400013b170, {ConnectivityState:READY ConnectionError:<nil>}"
2024/04/20 13:40:07 INFO: [core] [Channel #1]Channel Connectivity change to READY
2024/04/20 13:40:08 hello
2024/04/20 13:40:09 hello
2024/04/20 13:40:11 hello
...
```


## Wait-for-Readyありのログ
- 接続がなくなる最初に1度"could not invoke: rpc error: code = Unavailable desc = error reading from server: EOF"エラーが出ている
- それ以降新しい接続(10.0.30.165)を見つけるまで"could not invoke: "エラーは出ない
```
...
2024/04/20 13:43:26 hello
2024/04/20 13:43:27 hello
2024/04/20 13:43:28 hello
"2024/04/20 13:43:29 INFO: [transport] [client-transport 0x40000eb208] Closing: connection error: desc = ""error reading from server: EOF"""
2024/04/20 13:43:29 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE
"2024/04/20 13:43:29 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:<nil>}"
2024/04/20 13:43:29 INFO: [core] [Channel #1]Channel Connectivity change to IDLE
2024/04/20 13:43:29 INFO: [transport] [client-transport 0x40000eb208] loopyWriter exiting with error: transport closed by client
2024/04/20 13:43:29 could not invoke: rpc error: code = Unavailable desc = error reading from server: EOF
2024/04/20 13:43:30 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:30 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:30 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
2024/04/20 13:43:30 INFO: [core] [Channel #1]Channel Connectivity change to CONNECTING
"2024/04/20 13:43:30 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:30 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:30 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:30 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:30 INFO: [core] [Channel #1]Channel Connectivity change to TRANSIENT_FAILURE
"2024/04/20 13:43:31 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:31 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:31 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:31 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:31 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:43:31 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:31 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:31 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:31 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
"2024/04/20 13:43:32 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:32 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:32 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:32 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:32 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:43:32 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:32 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:32 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:32 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
"2024/04/20 13:43:35 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:35 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:35 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:35 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:35 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:43:35 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:35 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:35 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:35 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
"2024/04/20 13:43:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:39 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:39 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:43:39 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:39 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:39 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:39 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
"2024/04/20 13:43:40 could not invoke: rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:46 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
"2024/04/20 13:43:46 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:IDLE ConnectionError:connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused""}"
2024/04/20 13:43:46 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
"2024/04/20 13:43:46 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.27.158:50051"" to connect"
"2024/04/20 13:43:46 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:CONNECTING ConnectionError:<nil>}"
"2024/04/20 13:43:51 could not invoke: rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: connect: connection refused"""
2024/04/20 13:43:59 INFO: [core] [Channel #1]Resolver state updated: {
"  ""Addresses"": ["
    {
"      ""Addr"": ""10.0.30.165:50051"","
"      ""ServerName"": """","
"      ""Attributes"": null,"
"      ""BalancerAttributes"": null,"
"      ""Metadata"": null"
    }
"  ],"
"  ""Endpoints"": ["
    {
"      ""Addresses"": ["
        {
"          ""Addr"": ""10.0.30.165:50051"","
"          ""ServerName"": """","
"          ""Attributes"": null,"
"          ""BalancerAttributes"": null,"
"          ""Metadata"": null"
        }
"      ],"
"      ""Attributes"": null"
    }
"  ],"
"  ""ServiceConfig"": null,"
"  ""Attributes"": null"
} ()
2024/04/20 13:43:59 INFO: [core] [pick-first-lb 0x40001baed0] Received new config {
"  ""shuffleAddressList"": false"
"}, resolver state {"
"  ""Addresses"": ["
    {
"      ""Addr"": ""10.0.30.165:50051"","
"      ""ServerName"": """","
"      ""Attributes"": null,"
"      ""BalancerAttributes"": null,"
"      ""Metadata"": null"
    }
"  ],"
"  ""Endpoints"": ["
    {
"      ""Addresses"": ["
        {
"          ""Addr"": ""10.0.30.165:50051"","
"          ""ServerName"": """","
"          ""Attributes"": null,"
"          ""BalancerAttributes"": null,"
"          ""Metadata"": null"
        }
"      ],"
"      ""Attributes"": null"
    }
"  ],"
"  ""ServiceConfig"": null,"
"  ""Attributes"": null"
}
2024/04/20 13:43:59 INFO: [core] [Channel #1 SubChannel #2]addrConn: updateAddrs curAddr: {
"  ""Addr"": ""10.0.27.158:50051"","
"  ""ServerName"": ""server.grpc.local:50051"","
"  ""Attributes"": null,"
"  ""BalancerAttributes"": null,"
"  ""Metadata"": null"
"}, addrs: ["
  {
"    ""Addr"": ""10.0.30.165:50051"","
"    ""ServerName"": """","
"    ""Attributes"": null,"
"    ""BalancerAttributes"": null,"
"    ""Metadata"": null"
  }
]
"2024/04/20 13:43:59 INFO: [core] Creating new client transport to ""{Addr: \""10.0.27.158:50051\"", ServerName: \""server.grpc.local:50051\"", }"": connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: operation was canceled"""
"2024/04/20 13:43:59 WARNING: [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: ""10.0.27.158:50051"", ServerName: ""server.grpc.local:50051"", }. Err: connection error: desc = ""transport: Error while dialing: dial tcp 10.0.27.158:50051: operation was canceled"""
"2024/04/20 13:43:59 INFO: [core] [Channel #1 SubChannel #2]Subchannel picks a new address ""10.0.30.165:50051"" to connect"
2024/04/20 13:43:59 INFO: [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to READY
"2024/04/20 13:43:59 INFO: [core] [pick-first-lb 0x40001baed0] Received SubConn state update: 0x40001baf60, {ConnectivityState:READY ConnectionError:<nil>}"
2024/04/20 13:43:59 INFO: [core] [Channel #1]Channel Connectivity change to READY
2024/04/20 13:44:00 hello
2024/04/20 13:44:01 hello
2024/04/20 13:44:02 hello
...
```