Buyer times out processing piece

[bedeho]

This happens very frequently, and it leads to the connection being broken.

Its unclear why it is happening, but my leading hypothesis is that something is bad with the state management inside the extension, or that libtorrent is dropping the alert due to alert congestion.

Notes from Slack

this may be a good place to either add some debug prints, or to run in debug mode to see if any asserts fail

template <class ConnectionIdType> 
void Buying<ConnectionIdType>::receivedFullPiece(const ConnectionIdType & id, const protocol_wire::PieceData & p)

also adding logs to

void TorrentPlugin::on_piece_pass(int index)
void TorrentPlugin::on_piece_failed(int index)

where we see indexcan indication on whether libtorrent actually ever gets back to us about piece
thats a key question I think one thing which is different about the downloading we are doing now, is that it mixes paying and free pieces perhaps libtorrent is ignoring telling us about a piece it has already validated and stored here is the call we make to tell libtorrent about hte piece

here is the call we make to tell libtorrent about hte piece

        // Tell libtorrent to validate piece
        // last argument is a flag which presently seems to only test
        // flags & torrent::overwrite_existing, which seems to be whether
        // the piece should be overwritten if it is already present
        //
        // libtorrent::torrent_plugin::on_piece_pass()
        // libtorrent::torrent_plugin::on_piece_failed()
        // processes result of checking

        torrent()->add_piece(index, pieceData.piece().get(), 0);

perhaps logging before that line is also worth while

[mnaamani]

After adding some logging an reviewing the logs its clear the issue happens when peers are sending pieces that have been assigned to joystream peer, and a piece_pass event is triggered after the piece has been assigned to a joystream peer and before it arrives from the joystream peer.

Entering ReadyToRequestPiece state.
Reacting to RequestPiece event.
Entering WaitingForFullPiece state.
on_piece_pass 6
on_piece_pass 126
Reacting to Recv<wire::FullPiece> event.
Entering ProcessingPiece state.
checking piece 6 received on connection <- here we call torrent.add_piece()

The call to torrent.add_piece() as per the documentation "By default, data that's already been downloaded is not overwritten by this buffer." So this will not result in another piece_pass event. (My guess if the piece data was invalid it would also not result in a piece_failed event).

I will work on a fix for this, some things to think about:

We can use torrent.have_piece() to check if piece is already downloaded before trying to call torrent.add_piece().

Will need to find an alternate way to check if the joystream sent a valid piece.
If piece data was valid will need to directly call
protocol_session::Buying::receivedFullPiece .. but review to make sure it behaves correctly if it is called after protocol_session::Buying::pieceDownloaded (from on_piece_pass handler)

[mnaamani]

Working fix here: #45

[mnaamani]

Fix now in: #47