Cannot Fanout a head after contestation

[ghost]

Context & versions

I am testing hydra-chess run between 2 different MacOS machines running on a local network:

• hydra-node v0.14.0
• cardano-node v8.7.3
• hydra-chess @7c92130f8518bba5b6c4ec7e06dc9d55e654c6f5

Steps to reproduce

I don't know precisely 🤷 What I did is roughly the following:

• Configure the 2 hydra-chess apps to connect to each other
• Start a newTable which should open a head, which normally leads to each app posting a transaction to split the utxo committed
• Try to start a newGame
• Realise things seem to be wrong somehow, so stopping/restarting the apps while adding more feedback to the terminal UI to let users know what's happening
• Then I tried to stop the game which did not work, and finally Close the head from a WS client which worked but lead to a contestation being issued by one of the nodes
• Ultimately, I ended up not being able to Fanout from any of the 2 nodes

Actual behavior

The most concerning problem is that now:

1. When doing Fanout from node-1, the transaction fails because of an H24 error meaning the deadline is not reached
2. When doing Fanout from node-2, the transaction fails because of an H25 error meaning the snapshot hashes don't match

So the head state is in limbo blocked in a transaction on L1.

Moreover, I observed that the 2 acks from both nodes are not in sync and actually messages from node-1 are missing:

• node-2 has 5 messages stored and acks [16,5]
• node-1 has 16 messages stored and acks [16, 12]

This seem to implies some messages were not persisted correctly on node-2, something which is already known to be possible because the underlying persistence mechanism we use is not very robust.

I have attached the state and logs for both nodes

chess-1.tgz
chess-2.tgz

[ghost]

Here is a link to the contest transaction: https://preview.cexplorer.io/datum/bce3f5c87c7ef9447d8c382cccd01649bb9bf646934651f0777057390d7457c5
The produced datum is:

{
    "fields": [
        {
            "list": [
                {
                    "bytes": "18b42eb2fca922c893521b90386c00f32710888362138cc137c10b292eb8815c"
                },
                {
                    "bytes": "6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"
                }
            ]
        },
        {
            "int": 1
        },
        {
            "bytes": "3d8648a93151314d83ad8321df3700e5d8a6ed8bc41196f847c241add4e2864c"
        },
        {
            "int": 1705567787000
        },
        {
            "fields": [
                {
                    "int": 60000
                }
            ],
            "constructor": 0
        },
        {
            "bytes": "3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc"
        },
        {
            "list": [
                {
                    "bytes": "c312067b108b2ddd1a50ad1e757720570100fad3f14d6f88fd64ed42"
                }
            ]
        }
    ],
    "constructor": 2
}

so the contestation deadline is 1705567787000 which is Thursday, 18 January 2024 08:49:47 UTC

[ghost]

The validity range of the failing Fanout transaction is validity":{"notAfter":null,"notBefore":38911728} which is not straightforward to reconcile with the deadline but obviously it must be incorrectly computed.

[ghost]

I have tried to recover from this situation by:

1. wiping out hydra-node's state
2. restarting it from an earlier point in the chain so that it can observe all the head's transactions

But issuing a Fanout command still failed because of an evaluation error in the internal wallet, eg. the transaction is never sent to the chain. The script's error is H24 which denotes an incorrect hash. From the client I got the following messages:

{"peer":"hydra","seq":0,"tag":"PeerConnected","timestamp":"2024-01-19T07:29:30.262969Z"}
{"headId":"ed007cbddf75e2b66f854fd0a98a961880987066dc9b48b2f97448be","parties":[{"vkey":"18b42eb2fca922c893521b90386c00f32710888362138cc137c10b292eb8815c"},{"vkey":"6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"}],"seq":1,"tag":"HeadIsInitializing","timestamp":"2024-01-19T07:52:58.50813Z"}
{"headId":"ed007cbddf75e2b66f854fd0a98a961880987066dc9b48b2f97448be","party":{"vkey":"6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"},"seq":2,"tag":"Committed","timestamp":"2024-01-19T07:52:58.532014Z","utxo":{"0bc689a9f81ac49203886ae0a694120585c15d25fe41945dba5d235aa6b390eb#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}}}}
{"headId":"ed007cbddf75e2b66f854fd0a98a961880987066dc9b48b2f97448be","seq":3,"tag":"HeadIsAborted","timestamp":"2024-01-19T07:52:58.83091Z","utxo":{"0bc689a9f81ac49203886ae0a694120585c15d25fe41945dba5d235aa6b390eb#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}}}}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","parties":[{"vkey":"18b42eb2fca922c893521b90386c00f32710888362138cc137c10b292eb8815c"},{"vkey":"6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"}],"seq":4,"tag":"HeadIsInitializing","timestamp":"2024-01-19T07:53:01.519082Z"}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","party":{"vkey":"18b42eb2fca922c893521b90386c00f32710888362138cc137c10b292eb8815c"},"seq":5,"tag":"Committed","timestamp":"2024-01-19T07:53:01.536914Z","utxo":{"c889895821ab84a44bead4ef506c3ec0c4711f121cc8857a82ad83e6d7fea6d4#0":{"address":"addr_test1vrwf75x2cm3f9cdw4fpccerszrmlda8us5qspyhldjepeuc9r59du","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"dc9f50cac6e292e1aeaa438c647010f7f6f4fc85010092ff6cb21cf3":1},"lovelace":10000000}}}}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","party":{"vkey":"6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"},"seq":6,"tag":"Committed","timestamp":"2024-01-19T07:53:01.537317Z","utxo":{"b2648335649de06c497a3fa6b167c13ede05d988746fc4b67971c5daa7379574#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}}}}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","seq":7,"tag":"HeadIsOpen","timestamp":"2024-01-19T07:53:02.632887Z","utxo":{"b2648335649de06c497a3fa6b167c13ede05d988746fc4b67971c5daa7379574#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}},"c889895821ab84a44bead4ef506c3ec0c4711f121cc8857a82ad83e6d7fea6d4#0":{"address":"addr_test1vrwf75x2cm3f9cdw4fpccerszrmlda8us5qspyhldjepeuc9r59du","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"dc9f50cac6e292e1aeaa438c647010f7f6f4fc85010092ff6cb21cf3":1},"lovelace":10000000}}}}
{"contestationDeadline":"2024-01-18T08:48:47Z","headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","seq":8,"snapshotNumber":0,"tag":"HeadIsClosed","timestamp":"2024-01-19T07:53:03.410688Z"}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","seq":9,"snapshotNumber":1,"tag":"HeadIsContested","timestamp":"2024-01-19T07:53:03.45104Z"}
{"headId":"3ee6157268c7a3b7d21111b6772bc06aed0f425ef64b285223b308fc","seq":10,"tag":"ReadyToFanout","timestamp":"2024-01-19T07:53:03.552587Z"}
{"headStatus":"FanoutPossible","hydraNodeVersion":"0.14.0-0000000001000000000100000000010000000001","me":{"vkey":"6197ef01d4b8afab12850b1d0f3245b6b196c067dc17f2f86a001285b535a720"},"seq":11,"snapshotUtxo":{"b2648335649de06c497a3fa6b167c13ede05d988746fc4b67971c5daa7379574#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}},"c889895821ab84a44bead4ef506c3ec0c4711f121cc8857a82ad83e6d7fea6d4#0":{"address":"addr_test1vrwf75x2cm3f9cdw4fpccerszrmlda8us5qspyhldjepeuc9r59du","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"dc9f50cac6e292e1aeaa438c647010f7f6f4fc85010092ff6cb21cf3":1},"lovelace":10000000}}},"tag":"Greetings","timestamp":"2024-01-19T07:54:37.859151Z"}
{"tag": "Fanout"}
{"postChainTx":{"contestationDeadline":"2024-01-18T08:48:47Z","tag":"FanoutTx","utxo":{"b2648335649de06c497a3fa6b167c13ede05d988746fc4b67971c5daa7379574#0":{"address":"addr_test1vqdd0j63e83dvfgtmqpetfwfyrm0v29dcjcm6pt6s8ymaxqr3z3f6","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"1ad7cb51c9e2d6250bd80395a5c920f6f628adc4b1bd057a81c9be98":1},"lovelace":10000000}},"c889895821ab84a44bead4ef506c3ec0c4711f121cc8857a82ad83e6d7fea6d4#0":{"address":"addr_test1vrwf75x2cm3f9cdw4fpccerszrmlda8us5qspyhldjepeuc9r59du","datum":null,"datumhash":null,"inlineDatum":null,"referenceScript":null,"value":{"1f8f4076f72a0427ebe14952eb0709c046a49083baef749920cf6bfa":{"dc9f50cac6e292e1aeaa438c647010f7f6f4fc85010092ff6cb21cf3":1},"lovelace":10000000}}}},"postTxError":{"failureReason":"ValidationFailure (ValidationFailedV2 (CekError An error has occurred:  User error:\nThe machine terminated because of an error, either from a built-in function or from an explicit use of 'error'.) [\"H24\",\"PT5\"] PlutusDebug Omitted)","redeemerPtr":"RdmrPtr Spend 0","tag":"ScriptFailedInWallet","tx":{"body":{"fees":0,"inputs":["495878f0639aa2aed384af4b72bcdea058b339e6fd5fc6f63b5e7238d729
...

[ffakenz]

@ch1bo noticed the ContestObservation was not observing the contestationDeadline from chain, thus making it impossible for nodes to push deadline as expected.

It might be related and worth exploring as a potential solution to this.

[ch1bo]

Current plan is to reproduce this using the model based testing

[v0d1ch]

Node 2 - posted: CloseTx 2024-01-18T08:46:49.767738Z
Node 1 posted CloseTx 2024-01-18T08:47:04.28258Z
Node 2 NEVER sees close txid 94a7f0b86ee448dedf3667114f968dd825055bee4c90379a4659d8563b2e7d4a
Node 1 sees close tx id 5a4ed22b4e8137118eff07f26b366e031d880e66ebf11b3fafa130b50fc95441
Node 1 tries to re-post 94a7f0b86ee448dedf3667114f968dd825055bee4c90379a4659d8563b2e7d4a which fails with InsufficientCollateral 2024-01-18T08:47:28.58006Z
Node 2 - sees 5a4ed22b4e8137118eff07f26b366e031d880e66ebf11b3fafa130b50fc95441 OnCloseTx 2024-01-18T08:47:36.18Z
Node 1 - sees 5a4ed22b4e8137118eff07f26b366e031d880e66ebf11b3fafa130b50fc95441 OnCloseTx 2024-01-18T08:47:36.188861Z
Node 2 HeadIsClosed 2024-01-18T08:47:36.180545Z
Node 1 HeadIsClosed 2024-01-18T08:47:36.189005Z
Node 2 HeadIsReadyToFanout 2024-01-18T08:49:18.321568Z
Node 1 HeadIsReadyToFanout 2024-01-18T08:49:18.376381Z
Node 1 fails to post FanoutTx H25 2024-01-18T08:49:18.421306Z
Node 2 fails to post FanoutTx H24 2024-01-18T08:49:18.365115Z

[ch1bo]

Tried to make sense of the logs: https://github.com/input-output-hk/hydra/wiki/Logbook-2024-H1#sn-on-reproducing-the-contest-bug

Then, we drew this diagram today which should reflect the situation given by the logs:

Conclusion:

• Node 2 is expected to not be able to fanout as it was contested and it's missing the UTxO to hash (prove on-chain) (why a contest happened is maybe an orthogonal problem?)
• Node 1 should be able to fanout as it was the contesting party and the head is closed with it's snapshot