Aggressive deal-acceptance timeouts incompatible with external deal-gates ( e.g. CIDGravity ) #1478
Description
Checklist
- This is not a question or a support request. If you have any boost related questions, please ask in the discussion forum.
- This is not a new feature request. If it is, please file a feature request instead.
- This is not an enhancement request. If it is, please file a improvement suggestion instead.
- I have searched on the issue tracker and the discussion forum, and there is no existing related issue or discussion.
- I am running the
Latest release, or the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these. - I did not make any code changes to boost.
Boost component
- boost daemon - storage providers
- boost client
- boost UI
- boost data-transfer
- boost index-provider
- Other
Boost Version
N/A ( all current, up to 1.7.3, versions affected )
Describe the Bug
Whenever a proposal takes more than ~20-to-30 seconds, boost is closing the response stream. This results in the client never receiving an acceptance confirmation. In the log below please note that the time interval between this spot and this spot is 32 seconds, yet the client's connection was closed after barely 25s. It seems these timeout values are rather low. Additionally this defer not firing until scope-end might have something to do with.
What is common between affected SPs is usage of CIDGravity. I recommend raising the timeouts much higher, or alternatively setting the deadlines in a very tight space, only when the time to read/write has been reached.
A relevant log-excerpt from one of the affected SPs looks like:
2023-05-30T13:16:06.517+0200 INFO boost-net lp2pimpl/net.go:212 received deal proposal {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e", "client-peer": "12D3KooWPLStvTSmuZV9Vs4MF8N2cmWhLgSLnGysMkdE1PFrqojd"}
2023-05-30T13:16:06.517+0200 INFO boost-storage-deal logs/log.go:40 executing deal proposal received from network {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e", "peer": "12D3KooWPLStvTSmuZV9Vs4MF8N2cmWhLgSLnGysMkdE1PFrqojd"}
2023-05-30T13:16:06.526+0200 INFO boost-storage-deal logs/log.go:40 processing deal acceptance request {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e"}
2023-05-30T13:16:38.100+0200 INFO boost-storage-deal logs/log.go:40 offline deal accepted, waiting for data import {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e"}
2023-05-30T13:16:38.101+0200 INFO boost-prop lp2pimpl/net.go:227 send deal proposal response {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e", "accepted": true, "msg": "", "peer id": "12D3KooWPLStvTSmuZV9Vs4MF8N2cmWhLgSLnGysMkdE1PFrqojd", "client address": "f02090659", "provider address": "f0xxxxx", "piece cid": "baga6ea4seaqpqasbslkfmbalbel34zooc3vbt7anry5ozevho2c2o2ghiekwsfi", "piece size": 34359738368, "verified": true, "label": "baga6ea4seaqpqasbslkfmbalbel34zooc3vbt7anry5ozevho2c2o2ghiekwsfi", "start epoch": "2913270", "end epoch": "4445430", "price per epoch": "0"}
2023-05-30T13:16:38.101+0200 WARN boost-net lp2pimpl/net.go:247 writing deal response {"id": "e15695b7-bfb1-40ff-bb61-bc3a7562bc1e", "err": "stream reset"}
The corresponding proposer side:
proposal_uuid | proposal_took_msecs | failure
--------------------------------------+---------------------+--------------------------------------------------------------------
e15695b7-bfb1-40ff-bb61-bc3a7562bc1e | 24815 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
Client code is here, client-parameterized by a 90 second timeout: https://github.com/ribasushi/go-toolbox-interplanetary/blob/a1bf265b7762/lp2p/lp2p.go#L106-L163
Thanks to @aschmahmann for the help tracking it down.
Logging Information
Timing from the last few days as recorded from the proposer side ( ♠ custom code )
entry_created | proposal_delivered | provider_id | dialer | proposal_took_msecs | failure
-------------------------------+--------------------+-------------+--------------------------------------------------------+---------------------+--------------------------------------------------------------------
2023-05-30 12:56:19.753021+00 | | 1392893 | "12D3KooWQcNK4mEhX3TzQwBSizYCZqVMWc6RJuMsFRuR3mRTzw5g" | 20869 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 12:55:44.322711+00 | | 1392893 | "12D3KooWLZ57CGVHjti9pd9Q4oTnGRQ9JKqWhpcVP6j26yF3ABWz" | 21952 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 12:55:37.321375+00 | | 1392893 | "12D3KooWLZ57CGVHjti9pd9Q4oTnGRQ9JKqWhpcVP6j26yF3ABWz" | 28752 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 12:55:27.641419+00 | | 1392893 | "12D3KooWLZ57CGVHjti9pd9Q4oTnGRQ9JKqWhpcVP6j26yF3ABWz" | 29639 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 11:50:04.576412+00 | | 2095132 | "12D3KooWFbDkii8gUSxZUkyrZaVoNTYwL65VoPzAjFHZM1kEkt5m" | 24794 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 11:40:04.152476+00 | | 2095132 | "12D3KooWNtNGwvAUaoGtT4aRgSb1JkSFXXGiCTjbVoH9QdDRTrcu" | 24311 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 11:15:03.804598+00 | | 2095132 | "12D3KooWPLStvTSmuZV9Vs4MF8N2cmWhLgSLnGysMkdE1PFrqojd" | 24839 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 09:05:10.494584+00 | | 2033496 | "12D3KooWSrAC43gQvzNBUGmqkMaLF63ZphnhBmZvyKq5S6Sc94hX" | 34429 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 06:10:04.482461+00 | | 2095132 | "12D3KooWC33Q9UjG3NZa8TiGLF5hPem9ti1onTP2AbHG3FkQT1e4" | 26613 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 05:35:03.403389+00 | | 2095132 | "12D3KooWBq9aFwxW45dgEArSnXQ8N4uFwhn4xfpi3E5dyb9H8ZWo" | 27010 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 04:55:05.936857+00 | | 2095132 | "12D3KooWSejLdvDq2hecYhkeaftpteuypdmm1gi3p1h1JiTQAa46" | 27199 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-30 01:05:06.661002+00 | | 2095132 | "12D3KooWS1TtUTdDnYh5d3B3L94d3B4e3TMZNP8383QJdzv6ekjy" | 20636 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 23:20:02.970819+00 | | 2095132 | "12D3KooWDqtcjuiy5dLn6BxZ4p28PEGFpDZp2S3TtJkqTHPY4gNK" | 27202 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 18:55:03.248496+00 | | 2095132 | "12D3KooWEn7EusTq2eegEoL9CZHQJVHaHoP2vqx5HsdU19EiPUi2" | 26937 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 18:30:03.767547+00 | | 2033496 | "12D3KooWPToLRnCt58DckqT8HFXBsGaSAmpmbNJaMHQUoJ8dXhkH" | 24699 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 17:15:03.673154+00 | | 2095132 | "12D3KooWCvRD5jbSWi8myWcLiUk6ogxYqxdEaiEBJ9a6etDfYL28" | 21393 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 13:05:05.037146+00 | | 2095132 | "12D3KooWGZqXFdU9hJJ4xXrrBourH57Ntk9PqmzUoG9SkUhEURt1" | 36895 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 13:05:04.72069+00 | | 2095132 | "12D3KooWGZqXFdU9hJJ4xXrrBourH57Ntk9PqmzUoG9SkUhEURt1" | 26914 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 13:05:04.348167+00 | | 2095132 | "12D3KooWGZqXFdU9hJJ4xXrrBourH57Ntk9PqmzUoG9SkUhEURt1" | 26433 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 11:25:04.420411+00 | | 2095132 | "12D3KooWQvPBTisvYadmDdoQirqchZJV3pFLR3zqNAAALSB555EM" | 26917 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 11:25:04.094191+00 | | 2095132 | "12D3KooWQvPBTisvYadmDdoQirqchZJV3pFLR3zqNAAALSB555EM" | 26947 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 06:15:03.285072+00 | | 1771403 | "12D3KooWLiy2h2SsLjNiXAG7Ag9A1JCxYVw6uTbF5qsj8upRYrbn" | 27233 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 04:55:03.60162+00 | | 1771403 | "12D3KooWFSNo75fS8Rwec3uMf53YFMh8GPMwsziicNJbU5K9qqCo" | 26910 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 04:55:03.189758+00 | | 1771403 | "12D3KooWFSNo75fS8Rwec3uMf53YFMh8GPMwsziicNJbU5K9qqCo" | 27460 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 04:10:02.472707+00 | | 2095132 | "12D3KooWFngUKXhfQHiUXw4zk1TrBSKXnCYGGky3qa6r4R28g6qS" | 26544 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-29 03:52:39.915034+00 | | 2028544 | "12D3KooWL6rFs1eHQHAjd1XrpKRNmdsBmm3tMTteDSjPJp82XCXM" | 20848 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 16:30:02.94407+00 | | 2095132 | "12D3KooWCx9CXhRL8RA9i3435oegyJqfUXDh4Pw5uvKSAE5VvNTh" | 36450 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 16:00:03.227374+00 | | 2095132 | "12D3KooWNGqbyTJiMR9zmFF8ohqMK3oCWGbsx1TcWULgHfVxZJ3r" | 27305 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 13:50:03.336186+00 | | 2095132 | "12D3KooWJKodsAeArLUnzfEJ8fsxhggFSAhngHrUr5YK5uyBXFqH" | 27349 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 13:41:17.62437+00 | | 2028544 | "12D3KooWPByA5aQTWdXLNqGVhP8FTx3CjEkvbFEorW9vm8zKD3Jf" | 24359 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 11:45:03.815333+00 | | 2095132 | "12D3KooWMrS1MMH7HxvkiRYFbhfVE7RQ7pNXUEJLUcGoVeihKhan" | 26917 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 11:45:03.481105+00 | | 2095132 | "12D3KooWMrS1MMH7HxvkiRYFbhfVE7RQ7pNXUEJLUcGoVeihKhan" | 27110 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 11:10:06.405827+00 | | 2028544 | "12D3KooWHVPymhDcW1zrKqgb4FPAdaQv4dzg7czw5mCccF21rdSq" | 27916 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:10:03.605578+00 | | 2095132 | "12D3KooWP6wfBaoj483dGDB37H1i4wGXCrKjaC3fp7edQPvLq2ya" | 26898 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:10:03.292188+00 | | 2095132 | "12D3KooWP6wfBaoj483dGDB37H1i4wGXCrKjaC3fp7edQPvLq2ya" | 26716 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:05:04.761574+00 | | 2095132 | "12D3KooWA3TB5Ddw1Qt2UD8vMAsfPZ6YfHoRu6ec8T61QR6yv2iR" | 36905 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:05:04.393455+00 | | 2095132 | "12D3KooWA3TB5Ddw1Qt2UD8vMAsfPZ6YfHoRu6ec8T61QR6yv2iR" | 26907 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:05:04.05628+00 | | 2095132 | "12D3KooWA3TB5Ddw1Qt2UD8vMAsfPZ6YfHoRu6ec8T61QR6yv2iR" | 26912 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:05:03.712471+00 | | 2095132 | "12D3KooWA3TB5Ddw1Qt2UD8vMAsfPZ6YfHoRu6ec8T61QR6yv2iR" | 26912 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 10:05:03.389229+00 | | 2095132 | "12D3KooWA3TB5Ddw1Qt2UD8vMAsfPZ6YfHoRu6ec8T61QR6yv2iR" | 26695 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 09:45:05.314974+00 | | 2095132 | "12D3KooWPpxHeQ4RyVF68QxCHmdY6WuY1sPZuu6r7JfRCrbGwrYP" | 26911 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 09:45:04.996628+00 | | 2095132 | "12D3KooWPpxHeQ4RyVF68QxCHmdY6WuY1sPZuu6r7JfRCrbGwrYP" | 26907 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
2023-05-28 09:45:04.654522+00 | | 2095132 | "12D3KooWPpxHeQ4RyVF68QxCHmdY6WuY1sPZuu6r7JfRCrbGwrYP" | 26913 | "error while reading /fil/storage/mk/1.2.0 response: stream reset"
Repo Steps
Propose a cluster of deals, observe some of them failing.