Opened 11 years ago

Closed 11 years ago

#3121 closed Bug (invalid)

Stats not being reported during download

Reported by: Rain101 Owned by:
Priority: Normal Milestone: None Set
Component: Daemon Version: 1.92
Severity: Normal Keywords:
Cc:

Description

Running transmission-daemon 1.92 on Ubuntu Lucid. When I download a new torrent from a private tracker, it comes down fast, and starts seeding, but isn't reporting the traffic that occurs during the download phase to the tracker.

Once seeding, it does report ongoing traffic to the tracker.

I ran 1.92 breifly on an install of Hardy, and spotted something weird there too, but didn't investigate it fully enought to be able to say that it's the same issue.

Here's my situation: Fairly basic Hardy Install in a Vserver on a Debian Lenny box. Hardy (8.04) was then upgraded to Lucid (10.04B)

When using a private tracker, I observe the following behaviour: I start a torrent, it downloads *very* quickly (~10MB/sec), and is seeding at about 5MB/sec during that time. During this time, the tracker seems to be aware that I've started the download, but doesn't show how fast I'm going, or what % I have - nothing unusual there, as I'm not usually downloading for long, because it goes so fast. Once finished, the tracker seems to think I've got two clients connected - one downloading (it still doesn't know how much / how fast), the other seeding. It correctly credits me for these uploaded MB while seeding. The tracker does not seem to be aware of my download MB, or the uploads I do while I'm downloading.

I've successfully used the same tracker with the same usage pattern from a Debian Lenny install in a Vserver on the same Debian Lenny box. This was running a 1.77 deb from backports. No weird issues were apparent there. I have always had DHT off, but otherwise run a fairly stock setup.

What has changed:

  1. OS, Debian Lenny -> Ubuntu Lucid
  2. 1.77 -> 1.92
  3. ??

I'm not able to run a nightly, as the torrent community I'm in require that torrent clients be vetted. I've I'm running a beta client, and 'cheating' I'll get kicked for sure.

Attachments (1)

transmissionoutput (1.7 KB) - added by Rain101 11 years ago.
Output of transmission-remote <hostname> -t 10 -i

Download all attachments as: .zip

Change History (16)

Changed 11 years ago by Rain101

Output of transmission-remote <hostname> -t 10 -i

comment:1 Changed 11 years ago by livings124

I'm confused by what the bug is supposed to be. Do you expect the tracker to know your download progress as you download, as opposed to just when the app announces?

comment:2 Changed 11 years ago by Rain101

Right, I could have made that more clear.

Once seeding, it does report ongoing traffic to the tracker, but the tracker is never aware of traffic from the download phase.

If I'm downloading a 350MB file, and upload 400MB as it's downloading, and then do 125 MB of seeding after downloading the file, the total stats the tracker reports are: Downloaded: 0MB, Uploaded: 125MB.

What I would expect is: Downloaded: 350MB, Uploaded: 525MB.

Thanks, Pete

comment:3 Changed 11 years ago by livings124

Are you sure this isn't just the tracker not displaying the freshest stats? Transmission reports your total downloaded and uploaded when announcing.

comment:4 Changed 11 years ago by charles

  • Keywords incomplete needinfo added

I'm not seeing this bug at all. Also I've walked through the announce code very thoroughly and am not sure how a bug like that could occur unless you were to kill Transmission by hand immediately after becoming a seed s.t. the completion announce didn't go through.

My suggestion to you would be to run Transmission inside a terminal with the TRANSMISSION_CURL_VERBOSE environment variable set to 1, and redirect the output to a file, s.t. you can watch the announce messages to see what the "uploaded=X" value is.

in bash:

% TRANSMISSION_CURL_VERBOSE=1 transmission 2>/tmp/transmission-tracker-announce.log

comment:5 Changed 11 years ago by Rain101

Thanks for your update, In the end here's the command I ran:

debian-transmission@poison:/$ TRANSMISSION_CURL_VERBOSE=1 transmission-daemon --config-dir /var/lib/transmission-daemon/info/ 2> /tmp/transmission-tracker-announce.log

(there is no 'transmission' on my system just transmission-daemon - I assume that this is Debian/ubuntu's name for it).

Transmission seemed to start nicely & functionally run as expected, but nothing appeared in /tmp/transmission-tracker-announce.log

Looking in /var/log/daemon.log (where these logs normally go, I see a bunch of stuff about

Saved "/var/lib/transmission-daemon/infostats.json" (bencode.c:1645) and saving resume info,

One lin got me thinking about charles' comment: "not sure how a bug like that could occur unless you were to kill Transmission by hand immediately after becoming a seed s.t. the completion announce didn't go through."

Apr 8 03:48:03 poison transmission-daemon: a350MBfile.avi moving "/mnt/vsd/poison-incomplete/a350MBfile.avi" to "/mnt/vsd/downloads/a350MBfile.avi" (torrent.c:2505)

Could the 'move the finished file' routine be short-cutting the announce to the tracker? This is something I'll investigate as soon as I can & update you here.

Have you got any suggestions about what I'm doing wrong with getting curl debugging output?

Thanks for your help so far. Pete.

Last edited 11 years ago by Rain101 (previous) (diff)

comment:6 follow-up: Changed 11 years ago by Rain101

Yup, I can confirm that switching incomplete-dir-enabled to "false" has done the trick.

The tracker is now aware when I finish the download, and counts the stats of download and upload during the 'leech' phase (as well as counting the uploads that occur when seeding).

One other thing that I hadn't fully realised, before when it moved the download from the partial dir to the download dir, it was also disconnecting any peers that were downloading at the time. This is another side-effect that I hadn't anticipated.

So I'm fairly certain that it's a bug that the stats don't get reported as the torrent finishes the download phase.

Is it a bug that the torrent gets stopped, data file moved, then restarted? - is this a case of unexpected behaviour, or misaligned expectations?

Thanks for helping me get to the cause of this.

comment:7 Changed 11 years ago by Rain101

  • Keywords incomplete needinfo removed

comment:8 in reply to: ↑ 6 Changed 11 years ago by charles

Replying to Rain101:

Yup, I can confirm that switching incomplete-dir-enabled to "false" has done the trick. The tracker is now aware when I finish the download, and counts the stats of download and upload during the 'leech' phase (as well as counting the uploads that occur when seeding).

They are totally unrelated things. The announce code keeps trying to announce regardless of what else is going on. I suspect what happened in your test is that the announce succeeded and the tracker updated more quickly, and also coincidentally you had the incomplete dir turned off during the test.

If you're using the daemon, you'll need to run it in the foreground for the logging command I suggested earlier to work. Also, I made a mistake with the environment variable name; it's "TR_CURL_VERBOSE", not "TRANSMISSION_CURL_VERBOSE". Sorry about that.

Example in bash: "TR_CURL_VERBOSE=1 transmission-daemon -f 2>runlog"

One other thing that I hadn't fully realised, before when it moved the download from the partial dir to the download dir, it was also disconnecting any peers that were downloading at the time. This is another side-effect that I hadn't anticipated.

So I'm fairly certain that it's a bug that the stats don't get reported as the torrent finishes the download phase.

I'm not seeing this at all. I think the moved torrent is a red herring and would still like to see the log. :)

Is it a bug that the torrent gets stopped, data file moved, then restarted? - is this a case of unexpected behaviour, or misaligned expectations?

That would not stop an announce from happening. You would have to actually kill your Transmission process before the announce has a chance to go out over the network..

comment:9 Changed 11 years ago by Rain101

Alrighty, this is now running in a screen, and seems to be logging nicely.

Will let you know what I see. Might not be able to update for 9 or more hours.

Thanks,

Pete.

comment:10 Changed 11 years ago by Rain101

Right, about to add an snippet from todays log, but here's what I think is the most interesting lines:

[02:32:25.459] A1GBfile.mkv moving "/mnt/vsd/poison-incomplete/A1GBfile.mkv" to "/mnt/vsd/downloads/A1GBfile.mkv" (torrent.c:2505)
* About to connect() to tracker.domain.org port 80 (#0)
*   Trying 123.123.123.123...
* Connected to tracker.domain.org (123.123.123.123) port 80 (#0)
> GET /announce.php?passkey=32CDEADBEEFCAFEF00DDEADBEEFCAFEF&info_hash=1%EA%F1l%E8%8Cv%2Ep%84%BC%E8%F3vNj%2D%E2%B1s&peer_id=-TR1920-edd0o6d2t45l&port=51415&uploaded=1010840088&downloaded=1172740278&left=0&numwant=0&key=izhz4mqy&compact=1&supportcrypto=1&event=stopped HTTP/1.1
(snipout a few lines)
* Connected to tracker.domain.org (123.123.123.123) port 80 (#0)
> GET /announce.php?passkey=32CDEADBEEFCAFEF00DDEADBEEFCAFEF&info_hash=1%EA%F1l%E8%8Cv%2Ep%84%BC%E8%F3vNj%2D%E2%B1s&peer_id=-TR1920-edd0o6d2t45l&port=51415&uploaded=0&downloaded=0&left=0&numwant=200&key=izhz4mqy&compact=1&supportcrypto=1&event=started HTTP/1.1

The 'finish' get request looks complete & proper to my untrained eye. More detailed extract from the log about to be attached.

Pete.

Last edited 11 years ago by Rain101 (previous) (diff)

comment:11 Changed 11 years ago by charles

That behavior looks correct to me. I don't see the problem here...?

comment:12 Changed 11 years ago by Rain101

That's pretty well where I've gotten to as well. If the event=stopped get request looks good to you, then it must be just that the tracker ignores it. Which is strange, because it processes all the normal stop requests just fine.

Maybe the tracker ignores it because another update comes hard on it's heels (???) - doesn't make much sense to me.

Either way, I've found my workaround for now - disable the use of the partial directory until the tracker is fixed.

The way transmission deals with moving torrent data after the torrent has finished isn't quite what I had expected, and even if the tracker gets fixed, I probabally won't turn the partialdir function back on.

Thanks a lot for your troubleshooting advice, I now have some good data to feed back to the tracker admin.

Pete

comment:13 Changed 11 years ago by livings124

  • Resolution set to worksforme
  • Status changed from new to closed

comment:14 Changed 11 years ago by livings124

  • Resolution worksforme deleted
  • Status changed from closed to reopened

comment:15 Changed 11 years ago by livings124

  • Resolution set to invalid
  • Status changed from reopened to closed
Note: See TracTickets for help on using tickets.