search

arvidn / libtorrent

an efficient feature complete C++ bittorrent implementation
http://libtorrent.org
Other
5.16k stars 994 forks source link

WEB SEED FAILING (EOF) #3604

Closed BastienC09 closed 5 years ago

BastienC09 commented 5 years ago

libtorrent version (or branch): 0413ee581a1dd1959bce2b8c026825cb1cb7f973 LIBTORRENT_VERSION "1.2.0.0" LIBTORRENT_REVISION "c76e9cc5e"

platform/architecture: WIN10-x64 (Windows SDK version 10.0.17763.0 to target Windows 10.0.14393) My App is 32bits

compiler and compiler version: Visual Studio 2017 - Windows XP (v141_xp)

issue: I am experiencing issues using web seeds, for some reason suddenly the client seems to disconnect from the web seed leading to very slow download speed (that's how I noticed it), I have to pause/resume the torrent to go back to normal speed, until it fails again. I did not reproduce the problem with other clients so I suspect that this coming from my client. Sometimes I can download the whole file without errors.

I'll attach the log bellow (only with the messages containing the word "ERROR" from "lt::peer_log_alert"). I am intrigued by this error: _ERROR [ web_peerconnection error: End of file ]

Please let me know if you require more informations.

Torrent file: http://files.uvi.net:8080/SC62-Meteor/Meteor_1.1.2.torrent

Some Log:

*** PEER_ERROR [ op: 1 ERROR: (libtorrent:87) invalid HTTP range ]
 *** CONNECTION FAILED [ 86.201.51.113:46875 ERROR: (system:10060) A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond ]
*** CONNECTION_CLOSED [ op: 16 ERROR: (system:10060) A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond ]
*** CONNECTION FAILED [ 93.41.17.156:6881 ERROR: (system:10060) A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond ]
*** CONNECTION_CLOSED [ op: 16 ERROR: (system:10060) A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond ]
*** CONNECTION FAILED [ 86.201.51.113:6881 ERROR: (libtorrent:36) timed out ]
*** CONNECTION_FAILED [ op: 16 ERROR: (libtorrent:36) timed out ]
*** CONNECTION FAILED [ 93.41.17.156:58440 ERROR: (libtorrent:36) timed out ]
*** CONNECTION_FAILED [ op: 16 ERROR: (libtorrent:36) timed out ]
<<< ON_RECEIVE_DATA [ bytes: 0 ERROR: (asio.misc:2) End of file ]
*** ERROR [ in peer_connection::on_receive_data_impl ERROR: (asio.misc:2) End of file ]
*** ERROR [ web_peer_connection error: End of file ]
*** CONNECTION_CLOSED [ op: 11 ERROR: (asio.misc:2) End of file ]
BastienC09 commented 5 years ago

Some log update here, I noticed that I receive invalid HTTP range, don't know if I should worry about this:

00013b57: <info> Nagoya_Harp.rar [62.210.78.129:80] *** PEER_ERROR [ op: 1 ERROR: (libtorrent:87) invalid HTTP range ]
00013b58: <error> TORRENT: peer_error_alert: Nagoya_Harp.rar peer [ 62.210.78.129:80 client: Unknown ] peer error [bittorrent] [libtorrent]: invalid HTTP range
00013b59: <trace> TORRENT:  UNKNOWN ALERT: CATEGORY:16384 TYPE:80 MESSAGE:Nagoya_Harp.rar: removing web seed: "http://files.uvi.net/SC61-Nagoya_Harp/Nagoya_Harp_1.0.0/Nagoya_Harp.rar"

Also, I think I found when the speed starts dropping, here is the log, there is a reconnection to the web seed:

[2019-02-01 19:04:59.257576]: Meteor.rar [62.210.78.129:80] <<< ON_RECEIVE_DATA [ bytes: 0 ERROR: (asio.misc:2) End of file ]
[2019-02-01 19:04:59.257652]: Meteor.rar [62.210.78.129:80] *** ERROR [ in peer_connection::on_receive_data_impl ERROR: (asio.misc:2) End of file ]
[2019-02-01 19:04:59.257722]: Meteor.rar [62.210.78.129:80] *** ERROR [ web_peer_connection error: End of file ]
[2019-02-01 19:04:59.257801]: Meteor.rar [62.210.78.129:80] *** CONNECTION_CLOSED [ op: 11 ERROR: (asio.misc:2) End of file ]
[2019-02-01 19:04:59.257869]: Meteor.rar [62.210.78.129:80] *** SHORT_LIVED_DISCONNECT [  ]
[2019-02-01 19:04:59.257940]: TORRENT: peer_disconnected_alert: Meteor.rar peer [ 62.210.78.129:80 client: Unknown ] disconnecting (TCP) [sock_read] [asio.misc]: End of file (reason: 0)
[2019-02-01 19:04:59.258101]: Meteor.rar: *** PIECE_FINISHED [ p: 933 | chk: passed | size: 2097152 ]
[2019-02-01 19:04:59.258171]: Meteor.rar: PIECE_PASSED (1203)
[2019-02-01 19:04:59.258313]: Meteor.rar [62.210.78.129:80] <<< RECEIVED [ piece: 933 ]
[2019-02-01 19:04:59.258446]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1b4000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258527]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1b8000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258604]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1bc000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258680]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1c0000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258756]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1c4000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258831]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1c8000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258907]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1cc000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.258983]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1d0000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259059]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1d4000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259135]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1d8000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259210]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1dc000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259287]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1e0000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259364]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1e4000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259440]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1e8000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259516]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1ec000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259595]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1f0000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259671]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1f4000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259747]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1f8000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259822]: Meteor.rar [62.210.78.129:80] *** FILE_ASYNC_WRITE_COMPLETE [ piece: 933 s: 1fc000 l: 4000 e: Undefined error: 0 ]
[2019-02-01 19:04:59.259966]: Meteor.rar [62.210.78.129:80] >>> OUTGOING_CONNECTION [ ep: 62.210.78.129:80 type: TCP seed: 1 p: 0x6040001c0618 local: 0.0.0.0:0 ]
[2019-02-01 19:04:59.260051]: Meteor.rar [62.210.78.129:80] *** URL [ web_peer_connection http://files.uvi.net/SC62-Meteor/Meteor_1.1.2/Meteor.rar ]
[2019-02-01 19:04:59.260130]: Meteor.rar: web seed connection started: [62.210.78.129:80] http://files.uvi.net/SC62-Meteor/Meteor_1.1.2/Meteor.rar
[2019-02-01 19:04:59.260196]: Meteor.rar [62.210.78.129:80] *** SET_PEER_CLASS [ a: 62.210.78.129 ]
[2019-02-01 19:04:59.260269]: Meteor.rar [62.210.78.129:80] *** CLASS [ global tcp  ]
[2019-02-01 19:04:59.260542]: Meteor.rar [62.210.78.129:80] >>> OPEN [ protocol: IPv4 ]
[2019-02-01 19:04:59.260735]: Meteor.rar [62.210.78.129:80] >>> BIND [ dst: 0.0.0.0:0 ec: Undefined error: 0 ]
[2019-02-01 19:04:59.260819]: Meteor.rar [62.210.78.129:80] >>> ASYNC_CONNECT [ dst: 62.210.78.129:80 ]
[2019-02-01 19:04:59.260952]: TORRENT: peer_connect_alert: Meteor.rar peer [ 62.210.78.129:80 client: Unknown ] connecting to peer (TCP)
[2019-02-01 19:04:59.261032]: Meteor.rar [62.210.78.129:80] *** LOCAL ENDPOINT [ e: 192.168.1.13:64763 ]
[2019-02-01 19:04:59.261101]: Meteor.rar: START queue peer [0x1137eec20] (2)
[2019-02-01 19:04:59.261191]: Meteor.rar [62.210.78.129:80] *** UPDATE_INTEREST [ interesting, piece: 8 ]
[2019-02-01 19:04:59.261294]: Meteor.rar [62.210.78.129:80] *** CONNECTION CLOSED [  ]
[2019-02-01 19:04:59.261433]: TORRENT:  UNKNOWN ALERT: CATEGORY:2048 TYPE:57 MESSAGE:Meteor.rar: [1098] 97720 87 6199437 128 172840 0 0 172800 0 0
[2019-02-01 19:04:59.277729]: Meteor.rar [62.210.78.129:80] >>> COMPLETED [ ep: 62.210.78.129:80 ]
[2019-02-01 19:04:59.278012]: Meteor.rar [62.210.78.129:80] *** SET_NON_BLOCKING [  ]
[2019-02-01 19:04:59.278163]: Meteor.rar [62.210.78.129:80] >>> SET_TOS [ tos: 32 e: Undefined error: 0 ]
[2019-02-01 19:04:59.278283]: Meteor.rar [62.210.78.129:80] <== HAVE_ALL [  ]
[2019-02-01 19:04:59.278399]: Meteor.rar [62.210.78.129:80] *** SEED [ this is a seed p: 0x6040001c0618 ]
[2019-02-01 19:04:59.278531]: Meteor.rar [62.210.78.129:80] ==> INTERESTED [  ]
[2019-02-01 19:04:59.278652]: Meteor.rar [62.210.78.129:80] <== UNCHOKE [  ]
[2019-02-01 19:04:59.278772]: Meteor.rar [62.210.78.129:80] *** PIECE_PICKER [ dlq: 0 rqq: 0 target: 4 req: 4 engame: 0 ]
[2019-02-01 19:04:59.280792]: Meteor.rar [62.210.78.129:80] *** PIECE_PICKER [ prefer_contiguous: 1024 picked: 1024 ]
[2019-02-01 19:04:59.309505]: Meteor.rar [62.210.78.129:80] *** MERGING_REQUEST [ piece: 1665 block: 1 ]
[...... 1000+ LINES]
[2019-02-01 19:04:59.463717]: Meteor.rar [62.210.78.129:80] *** MERGING_REQUEST [ piece: 1672 block: 127 ]
[2019-02-01 19:04:59.463794]: Meteor.rar [62.210.78.129:80] ==> REQUESTING [ piece: 1665 start: 0 len: 16384 ]
[...... 1000+ LINES]
[2019-02-01 19:04:59.661842]: Meteor.rar [62.210.78.129:80] ==> REQUESTING [ piece: 1672 start: 2080768 len: 16384 ]
[2019-02-01 19:04:59.661947]: Meteor.rar [62.210.78.129:80] ==> REQUEST [ GET /SC62-Meteor/Meteor_1.1.2/Meteor.rar HTTP/1.1
Host: files.uvi.net
User-Agent: UVI Portal-0.6.0 (Mac OSX 10.13.6)
Connection: keep-alive
Range: bytes=3491758080-3508535295

 ]
[2019-02-01 19:04:59.662033]: Meteor.rar [62.210.78.129:80] >>> ASYNC_WRITE [ bytes: 182 ]
[2019-02-01 19:04:59.662158]: Meteor.rar [62.210.78.129:80] ==> REQUEST [ piece: 1665 s: 0 l: 1000000 ds: 0B/s dqs: 4 rqs: 1024 blk: large ]
[2019-02-01 19:04:59.662260]: Meteor.rar [62.210.78.129:80] >>> CORKED_WRITE [ bytes: 182 ]
[2019-02-01 19:04:59.662331]: Meteor.rar [62.210.78.129:80] <<< ASYNC_READ [ max: 17408 bytes ]
[2019-02-01 19:04:59.664929]: Meteor.rar [62.210.78.129:80] *** ON_SEND_DATA [ bytes: 182  ]
[2019-02-01 19:04:59.665011]: Meteor.rar [62.210.78.129:80] >>> WROTE [ 182 bytes ]
[2019-02-01 19:04:59.696121]: Meteor.rar [62.210.78.129:80] <<< ON_RECEIVE_DATA [ bytes: 1448  ]
[2019-02-01 19:04:59.696342]: Meteor.rar [62.210.78.129:80] <<< READ [ 1448 bytes ]
[2019-02-01 19:04:59.696601]: Meteor.rar [62.210.78.129:80] <== CHOKE [  ]
[2019-02-01 19:04:59.696723]: Meteor.rar [62.210.78.129:80] *** STATUS [ 206 Partial Content ]
[2019-02-01 19:04:59.696879]: Meteor.rar [62.210.78.129:80] *** STATUS [    accept-ranges: bytes ]
[2019-02-01 19:04:59.696982]: Meteor.rar [62.210.78.129:80] *** STATUS [    connection: close ]
[2019-02-01 19:04:59.697075]: Meteor.rar [62.210.78.129:80] *** STATUS [    content-disposition: attachment; filename="Meteor.rar" ]
[2019-02-01 19:04:59.697168]: Meteor.rar [62.210.78.129:80] *** STATUS [    content-length: 16777216 ]
[2019-02-01 19:04:59.697297]: Meteor.rar [62.210.78.129:80] *** STATUS [    content-range: bytes 3491758080-3508535295/6420946815 ]
[2019-02-01 19:04:59.697397]: Meteor.rar [62.210.78.129:80] *** STATUS [    content-type: application/octet-stream ]
[2019-02-01 19:04:59.697491]: Meteor.rar [62.210.78.129:80] *** STATUS [    date: Fri, 01 Feb 2019 18:04:59 GMT ]
[2019-02-01 19:04:59.697583]: Meteor.rar [62.210.78.129:80] *** STATUS [    etag: "17eb7df7f-56c3b929a2880" ]
[2019-02-01 19:04:59.697676]: Meteor.rar [62.210.78.129:80] *** STATUS [    last-modified: Tue, 15 May 2018 09:53:22 GMT ]
[2019-02-01 19:04:59.697768]: Meteor.rar [62.210.78.129:80] *** STATUS [    server: Apache/2.4.7 (Ubuntu) ]

Thanks for the help

BastienC09 commented 5 years ago

After more tests, actually the issue seemed to be elsewhere: When the torrent where only downloading from the webseed it was downloading perfectly (15 MO/s), but on a torrent with loads of other peers I was experiencing serious speed loss (50 KB/S).

Deactivating UTP solved the problem: enable_outgoing_utp: false enable_incoming_utp: false

arvidn commented 5 years ago

the better solution is to set mixed_mode_algorithm to prefer_tcp. The default is to throttle TCP based on the download rate achieved by peers. It's very primitive.

Seeker2 commented 5 years ago

"The default is to throttle TCP based on the download rate achieved by peers."

I thought only uTP peers/seeds would be used to regulate TCP speeds, so long as max upload speed has not been reached.

In any case, the causes of libtorrent's Poor uTP performance https://github.com/arvidn/libtorrent/issues/3542 need to be addressed.

arvidn commented 5 years ago

I thought only uTP peers/seeds would be used to regulate TCP speeds, so long as max upload speed has not been reached.

problem is, "max upload speed" is not known. It's roughly measured by the uTP congestion controller, and that's how it's estimated right now, to throttle TCP

Seeker2 commented 5 years ago

I typoed on that last message, I meant throttle TCP based on DOWNLOAD rate.

Running further with the wrong idea that the subject here was upload instead of download... By "max upload speed", I meant the user-set max value rather than calculated-based-on-estimates by the uTP congestion controller.

But for download speed, there's too many unknown unknowns. Even if every peer+seed max/usable speed is known both down and up, they could still try to upload to you at the same instant and briefly exceed any download limit -- either the max you set or the max measured by the uTP congestion controller. A seed has much more control over its upload speed than a peer has over its download speed, since only the seed can increase/decrease the upload amount. So any max download limit measured/determined by the uTP congestion controller has to be more on the conservative side than max upload limit. (But only true while only seeding -- downloading and uploading at the same time can see massive swings in upload-side overheads.)

Speeds can be pushed closer to maximums if only downloading from or uploading to 1 "fast" peer at a time, but that special case may not be worth adding.

Sadly, going by the original poster's experience...a special case probably does need to be added when downloading from a web seed while also downloading from multiple other seeds/peers on the same torrent. Or it could be uTP "pseudo-packet loss" is to blame which triggers the uTP congestion controller to vastly underestimate real max+usable speeds. "Pseudo-packet loss" because I have my suspicions that libtorrent (or at least Deluge's/qBT's implementation) is receiving/sending packets, it's just not processing them correctly or the messages it sends are corrupted but still count as uncorrupted packets by the receiving peer/seed as far as networking is concerned. (They pass packet CRC checks, just maybe improperly formatted for the BitTorrent message/s they contain.)

arvidn commented 5 years ago

yes, the throttling is very primitive, borderline a net negative. The main cases where it does not work well is when the swarm has a lot less upload capacity (to you) than a web seed, or when you have significantly higher network capacity than everyone else on the swarm, and you're not limited by your download capacity, but the sum of all peers' upload capacity.

uTorrent is a bit more sophisticated by instead adjusting the throttling over time, and keep letting more TCP through until it starts to affect the uTP streams.

I'm open to suggestions on simple ways to improve this. I fear that letting all web seeds through unthrottled would just always starve out the swarm entirely.

Seeker2 commented 5 years ago

Even assuming the libtorrent client's max download speed is smaller than the swarm's upload capacity (to it), how accurately can the uTP congestion controller estimate its max download speed?

5 second intervals may need to be averaged due to single-second bursts confounding the matter.

On the assumption that a web seed is only to be used if the peers+seeds cannot "satisfy" the libtorrent client, the web seed's available capacity may need to be separately known/estimated as well. Flash crowds arriving (lots of 0% complete peers at once) means this available capacity is likely painfully variable, so the web seed should only be used for rare pieces or desperately random pieces given equal rarity.