502 error during the pull

[mfarooq-tech]

Bug report:

I am getting Random 502 error (Bad gateway) for the pulls. Error for the dfdaemon is below. I have also attached scheduler log. Please note that I have disabled back to source.

{"level":"error","ts":"2021-10-13 05:07:33.330","caller":"peer/peertask_base.go:518","msg":"wait first peer packet from scheduler timeout, auto back source disabled","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).waitFirstPeerPacket\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:518\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:375"}
{"level":"error","ts":"2021-10-13 05:07:33.330","caller":"peer/peertask_base.go:377","msg":"wait first peer packet error","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:377"}
{"level":"error","ts":"2021-10-13 05:07:33.330","caller":"peer/peertask_stream.go:405","msg":"end piece result sent, peer task failed","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).cleanUnfinished.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:405\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).cleanUnfinished\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:401\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:372\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:378"}
{"level":"error","ts":"2021-10-13 05:07:33.330","caller":"peer/peertask_stream_callback.go:121","msg":"stream peer task failed, code: 4002, reason: wait first peer packet from scheduler timeout","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTaskCallback).Fail\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream_callback.go:121\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).cleanUnfinished.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:407\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).cleanUnfinished\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:401\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:372\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).pullPiecesFromPeers\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:378"}
{"level":"error","ts":"2021-10-13 05:07:33.338","caller":"peer/peertask_stream.go:269","msg":"wait first peer packet from scheduler timeout","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).Start\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:269\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTaskManager).StartStreamPeerTask\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_manager.go:240\nd7y.io/dragonfly/v2/client/daemon/transport.(*transport).download\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/transport/transport.go:181\nd7y.io/dragonfly/v2/client/daemon/transport.(*transport).RoundTrip\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/transport/transport.go:139\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/local/go/src/net/http/httputil/reverseproxy.go:284\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2867\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1932"}
{"level":"error","ts":"2021-10-13 05:07:33.338","caller":"transport/transport.go:193","msg":"download fail: wait first peer packet from scheduler timeout","peer":"a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad","component":"transport","stacktrace":"d7y.io/dragonfly/v2/client/daemon/transport.(*transport).download\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/transport/transport.go:193\nd7y.io/dragonfly/v2/client/daemon/transport.(*transport).RoundTrip\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/transport/transport.go:139\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/local/go/src/net/http/httputil/reverseproxy.go:284\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2867\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1932"}
{"level":"error","ts":"2021-10-13 05:07:51.910","caller":"client/client.go:175","msg":"ReportPeerResult: report peer result to scheduler dns:///e.f.g.h:8002 failed: rpc error: code = Canceled desc = context canceled","taskId":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","peerID":"a.b.c.d-1-80178e4a-2db2-4f98-8f8e-0b2504efd8ee","stacktrace":"d7y.io/dragonfly/v2/pkg/rpc/scheduler/client.(*schedulerClient).ReportPeerResult\n\t/go/src/d7y.io/dragonfly/v2/pkg/rpc/scheduler/client/client.go:175\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTaskCallback).Done\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream_callback.go:95\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).finish.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:389\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).finish\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:381\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).ReportPieceResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:234\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).ReportPieceResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:141\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).pushSuccessResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:163\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).DownloadPiece.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:97\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).DownloadPiece\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:159\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).downloadPieceWorker\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:664"}
{"level":"error","ts":"2021-10-13 05:07:51.910","caller":"peer/peertask_stream_callback.go:111","msg":"step 3: report successful peer result, error: rpc error: code = Canceled desc = context canceled","peer":"a.b.c.d-1-80178e4a-2db2-4f98-8f8e-0b2504efd8ee","task":"23c4567c005ffaafa85a77bba56d07e7d2a87db6b8dea4ad54ba049ec5b93b41","component":"streamPeerTask","stacktrace":"d7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTaskCallback).Done\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream_callback.go:111\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).finish.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:389\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).finish\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:381\nd7y.io/dragonfly/v2/client/daemon/peer.(*streamPeerTask).ReportPieceResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_stream.go:234\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).ReportPieceResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:141\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).pushSuccessResult\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:163\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).DownloadPiece.func1\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:97\nd7y.io/dragonfly/v2/client/daemon/peer.(*pieceManager).DownloadPiece\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/piece_manager.go:159\nd7y.io/dragonfly/v2/client/daemon/peer.(*peerTask).downloadPieceWorker\n\t/go/src/d7y.io/dragonfly/v2/client/daemon/peer/peertask_base.go:664"}

Expected behavior:

How to reproduce it:

Environment:

• Dragonfly version: v2.0.1-alpha.1
• OS:
• Kernel (e.g. uname -a):
• Others

[mfarooq-tech]

disableAutoBackSource: true

[jim3ma]

wait first peer packet from scheduler timeout, auto back source disabled
This says the scheduler did not schedule peers for peer a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad.
Search a.b.c.d-1-b10ebab8-1038-4fef-bb1e-0df580a17aad in all schedulers for details.

[mfarooq-tech]

I have attached the scheduler log

[jim3ma]

Same problem with #749 . Fixed in #756