WebSocket immediate disconnect on vasil-dev network

[rhyslbw]

What Git revision are you using?

e3b53aa

input-output-hk/cardano-configurations@77ad26a

What operating system are you using, and which version?

• Linux / Ubuntu
• Linux / Other
• OSX
• Windows

Describe what the problem is?

Connections made to the Ogmios server on vasil-dev result in an immediate WebSocket close:

Server logs

cardano-node-ogmios_1  | {"severity":"Error","timestamp":"2022-06-23T15:17:04.942155567Z","thread":"49","message":{"WebSocket":{"exception":"MuxError MuxBearerClosed \"<socket: 18> closed when reading data, waiting on next header True\"","tag":"WebSocketUnknownException"}},"version":"v5.5.0"}
cardano-node-ogmios_1  | {"severity":"Info","timestamp":"2022-06-23T15:17:04.942280371Z","thread":"49","message":{"WebSocket":{"tag":"WebSocketConnectionEnded","userAgent":"User-Agent unknown"}},"version":"v5.5.0"}

To reproduce

1. Start an instance of cardano-node-ogmios in the vasil-dev network.
2. Change

   ogmios/clients/TypeScript/packages/repl/src/index.ts

   Line 29 in e3b53aa

   const context = await createInteractionContext(console.error, () => {}, { connection })

   to: const context = await createInteractionContext(console.error, (code) => { log(code) }, { connection }) (not sure why I didn't log the disconnect in the initial impl) 😶
3. In clients/TypeScript run yarn repl:start --port __
4. Observe the disconnect code 1006

What should be the expected behavior?

Repeat steps 1,2, and 4 with a testnet instance to observe correct behaviour of no disconnect, and the ability to issue commands.

[KtorZ]

@rhyslbw silly question but, did you build the image with the right network configuration (a.k.a vasil-dev?). I just noticed, while trying on my end, that the first 'git clone' step was actually getting cached and, I ended up with a version of the config repository that was quite old, missing the vasil-dev configuration altogether.

I fixed that in: e4b0cdc and also added vasil-dev to the targets for the package workflow. I just tried pulling the image and running the container:

docker pull cardanosolutions/cardano-node-ogmios:latest-vasil-dev
docker run -it --name cardano-node-ogmios -p 1337:1337 cardanosolutions/cardano-node-ogmios:latest-vasil-dev

And so far, it seems to work fine outside of the TypeScript client but I do indeed observe this with the repl as well 🤔 ... I've been able to run pure JavaScript queries without problems, like:

import WebSocket from 'ws';

const client = new WebSocket("ws://localhost:1337");

client.on('message', e => {
  console.log(JSON.stringify(JSON.parse(e).result, null, 2));
  client.close();
});

client.on('open', () => {
  client.send(JSON.stringify({
    "type": "jsonwsp/request",
    "version": "1.0",
    "servicename": "ogmios",
    "methodname": "Query",
    "args": {
      "query": "ledgerTip"
    }
  }));
})

But somehow, the repl just dies.

[KtorZ]

Hmmm. It seems like the synchronization is stuck in Alonzo:

  "lastKnownTip": {
    "slot": 1325776,
    "hash": "c3cdc755cb6b91371432aa518b52c4e703d3df865d32471a9446af1444620362",
    "blockNo": 57825
  },
  "lastTipUpdate": "2022-06-26T09:16:33.156222502Z",
  "networkSynchronization": 0.77885,
  "currentEra": "Alonzo",

So I am thinking that perhaps, it is the background chain-sync that is just choking on the first Babbage's block.

edit: It is actually my local node which is stuck in Alonzo and can't seem to pass through:

[607ea45d:cardano.node.ConnectionManager:Info:8233] [2022-06-26 09:28:22.56 UTC] TrConnectionHandler (ConnectionId {localAddress = 172.17.0.2:3000, remoteAddress = 185.161.193.92:6012}) (TrError OutboundError (InvalidBlock (At (Block {blockPointSlot = SlotNo 1353978, blockPointHash = fa1358dfc38f7ea76fd90c790d5b38836adf4370588faf7bfaa48ed9d7e691ea})) 96cf886e78756937a7f4eaa02c14bc97ccaa9fcf226f5bae365ddd773683c890 (ValidationError (ExtValidationErrorLedger (HardForkLedgerErrorFromEra S (S (S (S (S (Z (WrapLedgerErr {unwrapLedgerErr = BBodyError (BlockTransitionError [ShelleyInAlonzoPredFail (LedgersFailure (LedgerFailure (UtxowFailure (FromAlonzoUtxowFail (PPViewHashesDontMatch SNothing (SJust (SafeHash "8ee004f99373941d6cbee99aab615d0c7fbab451faa9f115ef4587d66d0a77b5")))))))])})))))))))) ShutdownPeer)

[KtorZ]

So, this indeed happens as a result of running the chain-sync protocol and it doesn't seem related to a point on the chain. Indeed, if I run it in a pipelined mode, I can reach ~slot 400 008, but if I run a one-by-one mode, I don't even reach slot 50 000 before the connection closes. In all cases (tried out ~20 times with different modes and starting points), the connection closes after exactly 3.1s.

There's no trace in the node I could correlate to this. The connection is just abruptly closed.

[KtorZ]

I've tried on the testnet and mainnet and as far as I can tell, this behavior doesn't occur there. I wonder if this has anything to do with the issues regarding other peers (namely, the one using an invalid network magic and the one that is propagating bad blocks).

[rhyslbw]

Thanks @KtorZ

did you build the image with the right network configuration (a.k.a vasil-dev?)

I did a --no-cache build, so didn't hit the stale cache

I wonder if this has anything to do with the issues regarding other peers (namely, the one using an invalid network magic and the one that is propagating bad blocks).

🤔

[KtorZ]

Also, I just recalled: #208

Could it be that vasil-dev has p2p enabled ?

[catch-21]

@KtorZ Your node getting stuck is probably a result of using cardano-node:1.35.0-rc3. From RC4 that should not be a problem. Now it's best best to bump to 1.35.0. Also, in case Ogmios depends on the cost model, consider that alonzo-genesis file is missing PlutusV2 cost model.

[KtorZ]

Thanks @james-iohk. I'll get 1.35.0 integrated ASAP then. Regarding the configuration, we pull things from: https://book.world.dev.cardano.org/environments/vasil-dev

...and as far as I can see, there's no cost-model for PlutusV2 either in there. Ogmios would depend on this for execution units evaluation. Do you know what's up with this 😬 ?

[catch-21]

@KtorZ Yeah, the PlutusV2 cost model was excluded by mistake when vasil-dev was spun up. Then, instead of resetting the network, an update proposal was issued to include the V2 cost model. If possible, it would be safer for Ogmios to query the node for protocol params rather than depend on the file.

[KtorZ]

@james-iohk Ogmios actually uses the state query protocol already to resolve protocol parameters, since indeed, those may move with network updates.
So fine, it should be all covered 😊, it only needs the genesis as a starting point.

[KtorZ]

Trying to run the node with p2p disabled, I can confirmed that the behavior isn't present anymore. I can keep the repl open and do chain-sync just fine (or at least, for more than 3s and up until my current node's state). Though, I haven't yet figured what the topology configuration should be in non-p2p mode on vasil-dev, so my node is just hanging there not syncing.

This is the case also with 1.35.0. Running with EnableP2P causes the client connection to be terminated after 3s 🤷 ... And there's no trace on the node's side (even after enabling more logs on the local chain sync). I am.. puzzled.

[KtorZ]

What also puzzles me is that, there's also an internal client connection that Ogmios uses for the health heartbeat. This one is basically a chain-sync, and it remains up and running without problem 🤔

edit: So I've tried to artificially remove the health heartbeat and, it didn't solve the issue. However, I went a bit deeper in the rabbit hole and remove the second client connection made with each websocket (because each websocket actually starts two client connections, one for most protocols, and a side-one used to fetch protocols parameters & the like when submitting transactions or evaluating units). And this, seems to be the root cause of the issue. If I remove the second connection (which isn't needed for chain-sync) then the connection remains open (and even with the health heartbeat).

Now entering the realm of hypothesis: the second connection is mostly idle all-the-time, with the 'agency' on the client. So I think that the second connection is being terminated because it's idle, and thus, causes the first one to also terminates and the websocket to terminates in consequence. Thus, the exception we see "MuxBearerClosed" actually comes from us terminating the first connection, because the second is maybe terminated for some reason. I'll try to confirm that.

[KtorZ]

Hypothesis above ☝️ confirmed, so the second client (which is basically just idling waiting for a request) is indeed terminated automatically after ~3s somehow, causing the other to fail. If I simply add an error handling on that second client and forever restart it, then the rest seems fine.

So, we have a "quickfix" / mitigation, which is good. But it doesn't quite explain why the second client is terminated and why this only occurs when p2p is enabled (I'd expect p2p to be completely orthogonal to the local client protocols).