[Deal Making Issue] Retrieval (sometimes) fails with timeout waiting for data or funds request

[whyrusleeping]

I somewhat frequently get failures during retrieval where the miner accepts the deal and starts the transfer, but I end up getting a timeout waiting for them to either send data or request payment.
I have reprodiced this using estuary, lotus, and filc.
I have reproduced this against miners running 1.10.0, 1.11.0 and others.

Some sample failures:

    {
      "ID": 107,
      "CreatedAt": "2021-07-08T02:56:56.422246Z",
      "UpdatedAt": "2021-07-08T02:56:56.422246Z",
      "DeletedAt": null,
      "miner": "f024184",
      "phase": "retrieval",
      "message": "waitForPayment needed failed: timed out waiting for data or payment request",
      "content": 1747811,
      "cid": "QmcDQPbevysx1K9E1GyAhzLQktV4BArsa1TDU23y7hiZJp"
    },
    {
      "ID": 108,
      "CreatedAt": "2021-07-08T17:21:07.96582Z",
      "UpdatedAt": "2021-07-08T17:21:07.96582Z",
      "DeletedAt": null,
      "miner": "f010088",
      "phase": "retrieval",
      "message": "waitForPayment needed failed: timed out waiting for data or payment request",
      "content": 782294,
      "cid": "QmYGiJxgPYEzaXVrhBxdmCLk8b2MeJSXe1yyPXh19SLZGh"
    },
    {
      "ID": 110,
      "CreatedAt": "2021-07-08T17:21:29.324857Z",
      "UpdatedAt": "2021-07-08T17:21:29.324857Z",
      "DeletedAt": null,
      "miner": "f058369",
      "phase": "retrieval",
      "message": "waitForPayment needed failed: timed out waiting for data or payment request",
      "content": 782294,
      "cid": "QmYGiJxgPYEzaXVrhBxdmCLk8b2MeJSXe1yyPXh19SLZGh"
    },
    {
      "ID": 97,
      "CreatedAt": "2021-07-08T02:38:52.50989Z",
      "UpdatedAt": "2021-07-08T02:38:52.50989Z",
      "DeletedAt": null,
      "miner": "f023467",
      "phase": "retrieval",
      "message": "waitForPayment needed failed: timed out waiting for data or payment request",
      "content": 1747811,
      "cid": "QmcDQPbevysx1K9E1GyAhzLQktV4BArsa1TDU23y7hiZJp"
    },

[aarshkshah1992]

@whyrusleeping Please can you get us the DEBUG miner and client side logs for this ?

Miner

lotus-miner log set-level --system dt-impl --system dt-chanmon --system dt_graphsync --system markets --system data_transfer_network --system retrievaladapter --system retrieval --system stores --system markets-rtvl-reval debug

Client

lotus log set-level --system dt-impl --system dt-chanmon --system dt_graphsync --system markets --system data_transfer_network --system retrieval debug

[dirkmc]

It would also be good to know if there are any NAT issues between the client and provider, if it's possible to find out that information.

[hannahhoward]

@dirkmc this has a vibe that sounds similar to ipfs/go-graphsync#175 -- the issue that was breaking the concurrent deal tests -- that is solved by ipfs/go-graphsync#177 & filecoin-project/go-data-transfer#223. I wonder if they would help?

[hannahhoward]

note the issue those PRs fix is unfortunately MINER SIDE.

[raulk]

@whyrusleeping would you be able to get the logs that @aarshkshah1992 requested? We also merged the fix that Hannah pointed to and it should have shipped in go-graphsync v0.6.7/8. Have you seen this error recently?

[TippyFlitsUK]

Hi 👋

The Legacy Lotus Markets sub-system reached EOL at the end of the 31st January 2023.

This ticket is being marked as won't fix and closed as the Lotus Team will no longer be making any further fixes or enhancements to the legacy markets subsystem.

Please feel free to re-open this ticket in the new Boost markets sub-system repository at https://github.com/filecoin-project/boost if you feel that it is still relevant.

Many thanks 🙏