Lots of net_peercount errors on Alchemy node

[georgandreasjaksch]

I'm using the latest Docker version and it appears that using Alchemy as an upstream node produces a lot of the following errors:

Code: | -32601
-- | --
Message: | Unsupported method [net_peerCount]. See available methods at https://docs.alchemy.com/alchemy/documentation/apis

In the yaml it's not included in the list of supported methods as well as validation is gererally set to False.

Any idea what‘s wrong here?

[leogx9r]

See my reply on #152 (comment)

Had to disable Alchemy WS and just use JSON-RPC to bypass this.

[splix]

@georgandreasjaksch I guess it's a bug, it should not send net_peerCount if validation is disabled. Do you have it configured as a global option per blockchain or only for that specific upstream?

[georgandreasjaksch]

@splix I just set it individually for that upstream not as a global option. I'll give this a go and also try to remove the WS part from Alchemy config. Thx

[alexandre-abrioux]

I can confirm that the issue is still present in 0.13.0 (using the Docker image). Here is the upstream config I'm using:

upstreams:
  - id: alchemy-eth
    chain: ethereum
    priority: 100
    options:
      disable-validation: true
    labels:
      provider: alchemy
      archive: true
    connection:
      ethereum:
        rpc:
          url: "https://eth-mainnet.alchemyapi.io/v2/${ALCHEMY_USER}"
        ws:
          url: "wss://eth-mainnet.alchemyapi.io/v2/${ALCHEMY_USER}"

I still see a lot of net_peerCount requests in Alchemy's explorer, and in Dshackle logs I get the following:

...
2022-24-09 15:43:35.988 | INFO  | entMultistreamHolder | Upstream alchemy-eth with chain ETHEREUM has been added
2022-24-09 15:43:36.081 | WARN  |         AbstractHead | Restarting the Head...
2022-24-09 15:43:36.194 | INFO  |            StarterKt | Started StarterKt in 2.311 seconds (JVM running for 2.898)
2022-24-09 15:43:36.691 | INFO  |         WsConnection | Reconnect to wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key] in 100ms...
2022-24-09 15:43:36.703 | INFO  |         WsConnection | Disconnected from wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key]
2022-24-09 15:43:36.794 | INFO  |         WsConnection | Connecting to WebSocket: wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key]
2022-24-09 15:43:37.358 | INFO  |         WsConnection | Reconnect to wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key] in 100ms...
2022-24-09 15:43:37.359 | INFO  |         WsConnection | Disconnected from wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key]
2022-24-09 15:43:37.459 | INFO  |         WsConnection | Connecting to WebSocket: wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key]
2022-24-09 15:43:38.004 | INFO  |         WsConnection | Reconnect to wss://eth-mainnet.alchemyapi.io/v2/[hidden-api-key] in 100ms...
...

[nlordell]

From what I can tell disable-validation is not respected in the WebSocket connection. validate-peers is though, and can be used to work around this:

upstreams:
  - id: alchemy-eth
    chain: ethereum
    priority: 100
    options:
      validate-peers: false
    labels:
      provider: alchemy
      archive: true
    connection:
      ethereum:
        rpc:
          url: "https://eth-mainnet.alchemyapi.io/v2/${ALCHEMY_USER}"
        ws:
          url: "wss://eth-mainnet.alchemyapi.io/v2/${ALCHEMY_USER}"

[alexandre-abrioux]

I confirm, this removes the net_peerCount calls and works with Alchemy! Thanks, @nlordell!
However, I see a lot of errors after it starts, while this is not the case with Infura for instance.
I'm testing with 0.13.1 this time.

Failed to process WS message. class java.lang.IllegalStateException: State is not ready

Full logs:

2022-02-11 23:26:53.393 | INFO  |            StarterKt | Started StarterKt in 2.266 seconds (JVM running for 2.917)
2022-02-11 23:27:08.217 | INFO  |          Multistream | State of ETH: height=15885609, status=[UNAVAILABLE/1], lag=[0], weak=[alchemy-eth]
2022-02-11 23:27:23.212 | INFO  |          Multistream | State of ETH: height=15885610, status=[OK/1], lag=[0], weak=[]
2022-02-11 23:27:23.658 | WARN  |         WsConnection | Failed to process WS message. class java.lang.IllegalStateException: State is not ready
2022-02-11 23:27:38.211 | INFO  |          Multistream | State of ETH: height=15885612, status=[OK/1], lag=[0], weak=[]
2022-02-11 23:27:53.213 | INFO  |          Multistream | State of ETH: height=15885613, status=[OK/1], lag=[0], weak=[]
2022-02-11 23:27:53.659 | WARN  |         WsConnection | Failed to process WS message. class java.lang.IllegalStateException: State is not ready
2022-02-11 23:28:23.222 | INFO  |          Multistream | State of ETH: height=15885615, status=[OK/1], lag=[0], weak=[]
2022-02-11 23:28:23.662 | WARN  |         WsConnection | Failed to process WS message. class java.lang.IllegalStateException: State is not ready

[nlordell]

I am also seeing the occasional:

2022-03-11 08:01:15.241 | WARN  |         WsConnection | Failed to process WS message. class java.lang.IllegalStateException: State is not ready

It seems to happen reliably every 30s. My theory is that it may be something specific to the WebSocket server on the Alchemy side (I don't see this for local Geth connections or Infura for example).