Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Client randomly doesn't get a sole seed from the tracker #613

Closed
ManlyMarco opened this issue Jan 29, 2023 · 10 comments · Fixed by #623 or #624
Closed

Client randomly doesn't get a sole seed from the tracker #613

ManlyMarco opened this issue Jan 29, 2023 · 10 comments · Fixed by #623 or #624

Comments

@ManlyMarco
Copy link

ManlyMarco commented Jan 29, 2023

Tracker and sole seeder are hosted on the server, both using monotorrent.
The client receives a torrent file that uses this tracker and tries to start downloading it.
Seemingly randomly the tracker will report 0 peers. The seed seems to always get at least 1 peer from the tracker (itself). Using an external application to download the torrent instead of monotorrent seems to always receive the peer properly.
The download is forever stuck at 0 since there are no peers. Even waiting for a very long time doesn't seem to do anything.

These are the only events being fired after starting the torrent when it fails (hash is pre-checked).

[09:54:46] ScrapeComplete Successful=True Tracker=http://.../announce
[09:54:46] AnnounceComplete Successful=True Tracker=http://.../announce PeersCount=0
[09:54:46] PeersFound ExistingPeers=0 NewPeers=0

This is what happens when it works properly:

[11:05:06] ScrapeComplete Successful=True Tracker=http://.../announce
[11:05:07] AnnounceComplete Successful=True Tracker=http://.../announce PeersCount=1
[11:05:07] PeersFound ExistingPeers=-1 NewPeers=2
[11:05:08] PeerConnected Peer=ipv4://.../

Looks like there's a bunch of http/tracker exceptions being thrown when querying the tracker, but they seem to happen even if it succeedes.
image

Tested on latest master build on both client and server, but I believe it kept happening on latest beta build on nuget as well as the stable build.

This is pretty critical since I'm using private torrents so no DHT which would probably be able to sidestep the issue.

Edit: When there are multiple torrents running at the same time (all using that same tracker), it seems like some of them can succeed and some can fail to get the seed from the tracker.

@alanmcgovern
Copy link
Owner

alanmcgovern commented Feb 1, 2023

Hrm... That specific exception is suspect. It implies the underlying data is incomplete, i.e. a partial Http response was received.

Could you add a line of logging around this area of the code, probably prior to the if/else, to print out the content length of the response:

while ((bytesRead = await reader.ReadAsync (buffer, 0, (int) Math.Min (contentLength - totalRead, buffer.Length)).ConfigureAwait (false)) > 0) {

Also, if you dump the Memory stream to disk using System.Text.Encoding.ASCII to encode the bytes, it should be possible to eyeball the result and see what the content is. It might make it clearer whether the response is incomplete, or completely invalid.

@ManlyMarco
Copy link
Author

ManlyMarco commented Feb 1, 2023

Here's a dump of a failed response (copy of dataStream MemoryStream)

There is a lot of these being thrown:
image
It's all with family == AddressFamily.InterNetworkV6. I only enabled IPv4 on both the server and client with:
ListenEndPoints = new Dictionary<string, IPEndPoint> { { "ipv4", new IPEndPoint(IPAddress.Any, port) } },

Tracker has this as a sole listener, so I guess it's trying to only use IPv6?

var trackerEndpointHttp = $"*:{trackerPortHttp}";
var listenerHttp = TrackerListenerFactory.CreateHttp($"http://{trackerEndpointHttp}/announce/");

Edit: When the BEncodedValue.Decode fails the reply seems to be empty, writing the response to file results in 0 bytes.
response
empty headers

Not sure how to debug it from there. The response status code is "OK".
Edit2: Here's a wireshark capture, it looks like the issue might be on the server side?

@alanmcgovern
Copy link
Owner

It's all with family == AddressFamily.InterNetworkV6. I only enabled IPv4 on both the server and client with:

There's some cleanup which could be done here to reduce the frequency at which exceptions are thrown here, but it shouldn't make a difference to the actual behaviour or success of the library. The ipv6 tracker extensions state that the client should make both an ipv4 and ipv6 connection when announcing/scraping. If the tracker you're hosting only listens on ipv4, then the ipv6 announce from the client will fail. At this point the overall announce to the tracker will be considered a success as at least 1 announce variant succeeded. This way you can get ipv4 peers, ipv6 peers, or both ipv4+ipv6 peers.

Edit: When the BEncodedValue.Decode fails the reply seems to be empty, writing the response to file results in 0 bytes.

That's surprising! I'll review the TrackerServer code and try to see how this could happen. Actualy i just noticed the wireshark cap so i'll check that out first! Thanks!

@alanmcgovern
Copy link
Owner

alanmcgovern commented Feb 1, 2023

@ManlyMarco Is this capture from a time when the response appeared empty on the client side? If so, the bug has to be on the client side as the capture does show the response has the expected data, and contentlength.

Huh.

data_from_tracker

I'll assume this capture is from a time when the bug occurred and double check how HttpClient is reading the data.

Edit: Which .net framework version are you running under? I recently added a dependency on a 3rd party nuget as it was the only viable way of implementing the IPv6 tracker extensions, and I'm a little worried that the bug you're seeing is in that nuget.

If you're using .NET 4.7.2/4.8.x, could you try under .NET 6.0 and see if the behaviour is the same? If you're already using .NET 6.0 then it's definitely not that nuget.

alanmcgovern added a commit that referenced this issue Feb 2, 2023
When hosting a tracker, an unexpected exception looks like it
could cause an empty response to be sent to the client who
announced/scraped, while also setting a '200' success code.

Let's be really explicit here and log any unexpected errors
while also return an internal server error (status code 500)
if something unexpected really does occur.

Might help diagnose #613
@alanmcgovern
Copy link
Owner

I wonder if this will shed some light on the problem: #620

If you don't have logging enabled/redirected, you can redirect logging to a file by replacing Console.Out with a regular filestream/something and registering a function here. Note: You should do this right at the start of your app so everything initialises correctly.

https://github.com/alanmcgovern/monotorrent/blob/master/src/Samples/SampleClient/StandardDownloader.cs#L35

I have moderate hope this will identify the issue you're hitting :)

@ManlyMarco
Copy link
Author

ManlyMarco commented Feb 2, 2023

I'm using .NET Framework 4.7.2. Running the code in .NET 6.0 does seem to make a difference but it still throws an exception in the same spot, this time System.NotSupportedException: 'This protocol version is not supported.'. Either way it seems to work the same in the end. My ISP doesn't support IPv6 and neither does my server's ISP (also I disabled TCP/IPv6 in my network adapter properties), so these connections are expected to fail, but it's weird that it's even trying them when I specifically did not add ipv6 to ListenEndPoints. The exception is ultimately caught so it's fine as long as the actual ipv4 connection succeedes.

I'm trying to reproduce the issue with the more detailed logging enabled, but of course it doesn't happen when I'm trying to get it to happen. It seems to have fixed itself somehow, at least for now. I'll have to test it in the same environment as before tomorrorow. I'll keep the logging enabled and if the issue reappears I'll let you know.

For now I sidestepped the issue of unreliable tracker connection by manually adding the seed (I know it's IP since it's the same as the tracker given in the torrent file and the port never changes) and enabling peer exchange - this seems to always work.

@ManlyMarco
Copy link
Author

ManlyMarco commented Feb 2, 2023

Here's what I've got, it seems to randomly crash parsing the incoming tracker requests, but not all of them.
All of the torrents are created in the exact same way with only contained files and names being different. The same tracker is used for all of them. HTTP tracker is on port 15846 while the seed is on port 15847. Client uses port 15847 but is behind a VPN.

Client log (x is server IP):

[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - c
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - d
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - e
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - f
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - i
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - j
[16:09:39] [test torrent - i] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - j] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - d] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - c] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - f] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - e] ScrapeComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] [test torrent - d] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - i] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - k] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - c] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - j] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - m] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - b] AnnounceComplete Successful=True Tracker=http://xx.xx.xxx.xxx:15846/announce PeersCount=1
[16:09:39] [test torrent - b] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - d] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - c] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - m] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - i] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - k] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] [test torrent - j] PeersFound ExistingPeers=0 NewPeers=1
[16:09:39] INFO: ConnectionManager:Trying to connect to ipv4://xx.xx.xxx.xxx:15847/
[16:09:39] INFO: ConnectionManager:Trying to connect to ipv4://xx.xx.xxx.xxx:15847/
[16:09:39] INFO: ConnectionManager:Trying to connect to ipv4://xx.xx.xxx.xxx:15847/
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: Connection opened
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Sending handshake message with peer id '-MO3000-023404528852'
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: Connection opened
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Sending handshake message with peer id '-MO3000-023404528852'
[16:09:39] INFO: ConnectionManager:Trying to connect to ipv4://xx.xx.xxx.xxx:15847/
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - a
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - b
[16:09:39] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - m
[16:09:39] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: Connection opened
[16:09:39] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Sending handshake message with peer id '-MO3000-023404528852'
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: Connection opened
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Sending handshake message with peer id '-MO3000-023404528852'
[16:09:40] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - k
[16:09:40] INFO: HttpTrackerConnection:Tracker http://xx.xx.xxx.xxx:15846/announce sent 2 peers for InfoHash MonoTorrent.InfoHash
[16:09:40] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Received handshake message with peer id '-MO3000-182563814012'
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Received handshake message with peer id '-MO3000-182563814012'
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Received handshake message with peer id '-MO3000-182563814012'
[16:09:40] INFO: ConnectionManager:ipv4://xx.xx.xxx.xxx:15847/: [outgoing] Received handshake message with peer id '-MO3000-182563814012'
[16:09:41] INFO: HttpTrackerConnection:Unknown scrape tag received: Key name  Value test torrent - k
[16:09:41] INFO: TrackerTier:Announced to http://xx.xx.xxx.xxx:15846/announce

Server log (y is client IP):

ERROR:HttpTrackerListener:Error processing announce from peer
System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values. (Parameter 'port')
   at System.Net.IPEndPoint..ctor(IPAddress address, Int32 port)
   at MonoTorrent.TrackerServer.AnnounceRequest..ctor(NameValueCollection collection, IPAddress address)
   at MonoTorrent.Connections.TrackerServer.TrackerListener.Handle(NameValueCollection collection, IPAddress remoteAddress, Boolean isScrape)
   at MonoTorrent.Connections.TrackerServer.TrackerListener.Handle(String queryString, IPAddress remoteAddress, Boolean isScrape)
   at MonoTorrent.Connections.TrackerServer.HttpTrackerListener.ProcessContextAsync(HttpListenerContext context, CancellationToken token)
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:58411/: ConnectionReceived
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:50603/: ConnectionReceived
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:52429/: ConnectionReceived
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:41189/: ConnectionReceived
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:50603/: [incoming] Received handshake with peer_id '-MO3000-023404528852'
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:50603/: Handshake successful handled
INFO: ConnectionManager:ipv4://yyy.yyy.yy.yyy:50603/: Incoming connection fully accepted
INFO: ConnectionManager:Incoming connection fully accepted
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:58411/: [incoming] Received handshake with peer_id '-MO3000-023404528852'
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:58411/: Handshake successful handled
INFO: ConnectionManager:ipv4://yyy.yyy.yy.yyy:58411/: Incoming connection fully accepted
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:52429/: [incoming] Received handshake with peer_id '-MO3000-023404528852'
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:52429/: Handshake successful handled
INFO: ConnectionManager:ipv4://yyy.yyy.yy.yyy:52429/: Incoming connection fully accepted
INFO: ConnectionManager:Incoming connection fully accepted
INFO: ConnectionManager:Incoming connection fully accepted
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:41189/: [incoming] Received handshake with peer_id '-MO3000-023404528852'
INFO: ListenManager:ipv4://yyy.yyy.yy.yyy:41189/: Handshake successful handled
INFO: ConnectionManager:ipv4://yyy.yyy.yy.yyy:41189/: Incoming connection fully accepted
INFO: ConnectionManager:Incoming connection fully accepted
ERROR:HttpTrackerListener:Error processing announce from peer
System.ArgumentOutOfRangeException: Specified argument was out of the range of valid values. (Parameter 'port')
   at System.Net.IPEndPoint..ctor(IPAddress address, Int32 port)
   at MonoTorrent.TrackerServer.AnnounceRequest..ctor(NameValueCollection collection, IPAddress address)
   at MonoTorrent.Connections.TrackerServer.TrackerListener.Handle(NameValueCollection collection, IPAddress remoteAddress, Boolean isScrape)
   at MonoTorrent.Connections.TrackerServer.TrackerListener.Handle(String queryString, IPAddress remoteAddress, Boolean isScrape)
   at MonoTorrent.Connections.TrackerServer.HttpTrackerListener.ProcessContextAsync(HttpListenerContext context, CancellationToken token)

@alanmcgovern
Copy link
Owner

alanmcgovern commented Feb 2, 2023

Ah interesting! It looks like perhaps a default port is propagating to the tracker, instead of being replaced with the actual listen port the client is using.

There are two fixes:

  1. The tracker should be made robust against this. If an invalid port is sent, it should replace it with '0' and send a warning back to the client after fulfilling the announce. This is what the warning part of the announce response is for!

  2. Figure out why the client is sending a port of -1. I assume this is what's happening based on the exception and the fact -1 is the default here:

            Func<string, (string?, int)> reportedAddressFunc = type => {
                string? ip = null;
                int port = engine.GetOverrideOrActualListenPort (type).GetValueOrDefault (-1);
                if (engine.Settings.ReportedListenEndPoints.TryGetValue (type, out var reportedAddress))
                    ip = reportedAddress.Address.ToString ();
                return (ip, port);
            };

The implementation of that is:

if (Settings.ReportedListenEndPoints.TryGetValue(scheme, out var endPoint) && endPoint.Port != 0)
return endPoint.Port;
foreach (var listener in PeerListeners) {
if (scheme == "ipv4" && listener.LocalEndPoint != null && listener.LocalEndPoint.AddressFamily == AddressFamily.InterNetwork)
return listener.LocalEndPoint.Port;
if (scheme == "ipv6" && listener.LocalEndPoint != null && listener.LocalEndPoint.AddressFamily == AddressFamily.InterNetworkV6)
return listener.LocalEndPoint.Port;
}
return null;

and from that I assume either the announce is happening before the IPv4 listener has bound to a local port... or something else funky is going on. I wonder if there should be another fallback, which is to just return the port you configured the listener with. If it was configured with a specific port (i.e. 12345) that value can be sent to the tracker even if the listener has not yet successfully bound to that port (potentially because some other app is currently using the port).

alanmcgovern added a commit that referenced this issue Feb 2, 2023
When hosting a tracker, an unexpected exception looks like it
could cause an empty response to be sent to the client who
announced/scraped, while also setting a '200' success code.

Let's be really explicit here and log any unexpected errors
while also return an internal server error (status code 500)
if something unexpected really does occur.

Might help diagnose #613
@alanmcgovern
Copy link
Owner

This should be fixed in master now!

@ManlyMarco
Copy link
Author

Confirming the issue is fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants