I'm trying to write a basic BitTorrent client as a personal project and I've ran into this issue of peers sending me different byte offsets than what I requested. The strange bit is is that this happens about 50% of the time. Is this a normal part of the protocol? I've done some tests so far and concluded that this happens:
- regardless of piece index
- regardless of peer
Requested block lengths are never over 16kb. For debugging purposes I download a single piece from a single peer.
Here's a log dump of the issue occurring:
2023-06-18 14:18:51,903 - INFO - piece index: 748
2023-06-18 14:18:51,903 - INFO - requested byte offset 0 and got 0
2023-06-18 14:18:53,898 - INFO - piece index: 748
2023-06-18 14:18:53,898 - INFO - requested byte offset 16384 and got 16384
2023-06-18 14:18:55,905 - INFO - piece index: 748
2023-06-18 14:18:55,905 - INFO - requested byte offset 32768 and got 32768
2023-06-18 14:18:55,968 - INFO - piece index: 748
2023-06-18 14:18:55,968 - INFO - requested byte offset 16384 and got 0
2023-06-18 14:18:57,935 - INFO - piece index: 748
2023-06-18 14:18:57,935 - INFO - requested byte offset 49152 and got 49152
2023-06-18 14:18:59,961 - INFO - piece index: 748
2023-06-18 14:18:59,961 - INFO - requested byte offset 81920 and got 81920
2023-06-18 14:19:00,007 - INFO - piece index: 748
2023-06-18 14:19:00,007 - INFO - requested byte offset 65536 and got 16384
2023-06-18 14:19:01,973 - INFO - piece index: 748
2023-06-18 14:19:01,973 - INFO - requested byte offset 98304 and got 98304
2023-06-18 14:19:03,983 - INFO - piece index: 748
2023-06-18 14:19:03,983 - INFO - requested byte offset 131072 and got 131072
2023-06-18 14:19:04,077 - INFO - piece index: 748
2023-06-18 14:19:04,077 - INFO - requested byte offset 114688 and got 65536
2023-06-18 14:19:06,007 - INFO - piece index: 748
2023-06-18 14:19:06,007 - INFO - requested byte offset 147456 and got 147456
2023-06-18 14:19:08,018 - INFO - piece index: 748
2023-06-18 14:19:08,018 - INFO - requested byte offset 180224 and got 180224
2023-06-18 14:19:08,096 - INFO - piece index: 748
2023-06-18 14:19:08,096 - INFO - requested byte offset 163840 and got 114688
2023-06-18 14:19:10,012 - INFO - piece index: 748
2023-06-18 14:19:10,012 - INFO - requested byte offset 196608 and got 196608
2023-06-18 14:19:12,035 - INFO - piece index: 748
2023-06-18 14:19:12,035 - INFO - requested byte offset 229376 and got 229376
2023-06-18 14:19:12,098 - INFO - piece index: 748
2023-06-18 14:19:12,098 - INFO - requested byte offset 212992 and got 163840
And a log dump of getting a valid piece:
2023-06-18 14:20:13,296 - INFO - piece index: 748
2023-06-18 14:20:13,296 - INFO - requested byte offset 0 and got 0
2023-06-18 14:20:15,291 - INFO - piece index: 748
2023-06-18 14:20:15,291 - INFO - requested byte offset 16384 and got 16384
2023-06-18 14:20:17,314 - INFO - piece index: 748
2023-06-18 14:20:17,314 - INFO - requested byte offset 32768 and got 32768
2023-06-18 14:20:19,323 - INFO - piece index: 748
2023-06-18 14:20:19,323 - INFO - requested byte offset 49152 and got 49152
2023-06-18 14:20:21,330 - INFO - piece index: 748
2023-06-18 14:20:21,330 - INFO - requested byte offset 65536 and got 65536
2023-06-18 14:20:23,359 - INFO - piece index: 748
2023-06-18 14:20:23,359 - INFO - requested byte offset 81920 and got 81920
2023-06-18 14:20:25,387 - INFO - piece index: 748
2023-06-18 14:20:25,387 - INFO - requested byte offset 98304 and got 98304
2023-06-18 14:20:27,410 - INFO - piece index: 748
2023-06-18 14:20:27,410 - INFO - requested byte offset 114688 and got 114688
2023-06-18 14:20:29,408 - INFO - piece index: 748
2023-06-18 14:20:29,408 - INFO - requested byte offset 131072 and got 131072
2023-06-18 14:20:31,404 - INFO - piece index: 748
2023-06-18 14:20:31,404 - INFO - requested byte offset 147456 and got 147456
2023-06-18 14:20:33,440 - INFO - piece index: 748
2023-06-18 14:20:33,440 - INFO - requested byte offset 163840 and got 163840
2023-06-18 14:20:35,450 - INFO - piece index: 748
2023-06-18 14:20:35,450 - INFO - requested byte offset 180224 and got 180224
2023-06-18 14:20:37,475 - INFO - piece index: 748
2023-06-18 14:20:37,475 - INFO - requested byte offset 196608 and got 196608
2023-06-18 14:20:39,466 - INFO - piece index: 748
2023-06-18 14:20:39,466 - INFO - requested byte offset 212992 and got 212992
2023-06-18 14:20:41,477 - INFO - piece index: 748
2023-06-18 14:20:41,477 - INFO - requested byte offset 229376 and got 229376
2023-06-18 14:20:43,483 - INFO - piece index: 748
2023-06-18 14:20:43,483 - INFO - requested byte offset 245760 and got 245760
I'm expecting the exact byte offset that I requested though peers occasionally send different offsets.
Note that the bittorrent protocol consists of two asynchronous message streams (one for each direction) and clients are allowed to fulfill requests out of order. So you'll have to make sure that you're actually looking at the correct messages, you might be getting blocks from a different piece for example, so make sure to check the actual piece number in the message, not just the one you're expecting.
Try checking with wireshark if its interpetation of the message stream agrees with what your client is seeing.
It's generally possible that remote peers are buggy, but a 50% error rate is unusual and makes it more likely that the error is on your end. Maybe an endianness issue?