503 error from node results in continued retry until timeout

[gregscullard]

Description

Today, two nodes have a partial outage (0.0.4 and 0.0.7) on mainnet, specifying a node list in the client which includes one of these and a known working node results in inconsistent behaviour.

When a failing node is picked, the SDK retries until it times out, it doesn't attempt to connect to the other working node (see error/stack trace below)

Adding .setNodeAccountIds(List.of(new AccountId(4), new AccountId(3))) to the transaction builder results in the same outcome.

Note this happens with 2.1.0-beta and not 2.1.0

Steps to reproduce

        Map<String, AccountId> network = new HashMap<String, AccountId>();
        network.put("35.237.200.180:50211", new AccountId(3));
        network.put("35.186.191.247:50211", new AccountId(4));
        Client client = Client.forNetwork(network);
        client.setOperator(OPERATOR_ID, OPERATOR_KEY);

        // Generate a Ed25519 private, public key pair
        PrivateKey newKey = PrivateKey.generate();
        PublicKey newPublicKey = newKey.getPublicKey();

        System.out.println("private key = " + newKey);
        System.out.println("public key = " + newPublicKey);

        TransactionResponse transactionResponse = new AccountCreateTransaction()
            // The only _required_ property here is `key`
            .setKey(newPublicKey)
            .setInitialBalance(Hbar.from(1000))
            .execute(client);

Additional context

[hedera-sdk-2] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Retrying node 0.0.4 in 250 ms after failure during attempt #1: UNAVAILABLE: HTTP status code 503
invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

[hedera-sdk-2] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Using unhealthy node 0.0.4. Delaying attempt #2 for 1634045538749 ms
[hedera-sdk-4] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Retrying node 0.0.4 in 1000 ms after failure during attempt #3: UNAVAILABLE: HTTP status code 503
invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

[hedera-sdk-4] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Using unhealthy node 0.0.4. Delaying attempt #4 for 1634045539396 ms
[hedera-sdk-6] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Retrying node 0.0.4 in 4000 ms after failure during attempt #5: UNAVAILABLE: HTTP status code 503
invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

[hedera-sdk-6] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Using unhealthy node 0.0.4. Delaying attempt #6 for 1634045540542 ms
[hedera-sdk-8] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Retrying node 0.0.4 in 8000 ms after failure during attempt #7: UNAVAILABLE: HTTP status code 503
invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

[hedera-sdk-8] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Using unhealthy node 0.0.4. Delaying attempt #8 for 1634045542679 ms
[hedera-sdk-10] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Retrying node 0.0.4 in 8000 ms after failure during attempt #9: UNAVAILABLE: HTTP status code 503
invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

[hedera-sdk-10] WARN com.hedera.hashgraph.sdk.AccountCreateTransaction - Using unhealthy node 0.0.4. Delaying attempt #10 for 1634045546814 ms
Exception in thread "main" java.lang.RuntimeException: java.lang.Exception: Failed to get gRPC response within maximum retry count
at com.hedera.hashgraph.sdk.WithExecute.execute(WithExecute.java:51)
at com.hedera.hashgraph.sdk.WithExecute.execute(WithExecute.java:34)
at CreateAccountExample.main(CreateAccountExample.java:68)
Caused by: java.lang.Exception: Failed to get gRPC response within maximum retry count
Caused by: java.lang.Exception: Failed to get gRPC response within maximum retry count

at com.hedera.hashgraph.sdk.Executable.executeAsync(Executable.java:185)
at com.hedera.hashgraph.sdk.Executable.lambda$executeAsync$1(Executable.java:197)
at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1146)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1806)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
at java.base/java.lang.Thread.run(Thread.java:832)

Caused by: io.grpc.StatusRuntimeException: UNAVAILABLE: HTTP status code 503
Caused by: io.grpc.StatusRuntimeException: UNAVAILABLE: HTTP status code 503

invalid content-type: text/html
headers: Metadata(:status=503,content-length=107,cache-control=no-cache,content-type=text/html)
DATA-----------------------------

503 Service Unavailable

No server is available to handle this request.

DATA-----------------------------

at io.grpc.Status.asRuntimeException(Status.java:535)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:557)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:69)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:738)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:717)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
... 3 more

Hedera network

mainnet

Version

2.1.0-beta

Operating system

macOS

[janaakhterov]

I believe the reason this happens is because by default requests will use 1/3rd the nodes on the network, and in your case that would be 1. Along with that we de-prioritize unhealthy nodes without removing them from the network so if a node starts working again it'll be used again. The max backoff for a node I believe is 8 seconds so every 8 seconds it'll likely be picked as a requests node causing the request to fail. To resolve the issue you can either set Client.setMaxNodeAttempts(1) to allow the network to remove unresponsive nodes, or you can set the node account IDs for each request to be client.getNetwork().values() (all the nodes of the network) since your network only contains 2 nodes.

[SimiHunjan]

issue resolved in v2.1.0