Jump to content

Occasionally a torrent goes to seeding and the finish download script is not run


dsm1212

Recommended Posts

Once in a while I've had a download not finish correctly. The download stays in the busy/working directory and is not moved to the completed directory. Also, the finished script is not run even though it says "seeding" an is 100% done. I'm running 3.3 (30470 build). The only way to get the thing to finish is to remove the torrent and start it again. It recovers in a minute or so from the data that is in the working directory and then finishes it normally. I can't reproduce this at will. It's happened 3 out of about 25 downloads.

 

steve

Link to comment
Share on other sites

  • 1 month later...

I can't reproduce this at will. It's happened 3 out of about 25 downloads.

It will be difficult to work on this if there isn't a consistent way to reproduce it.  However, logging may show something useful.  Can you log everything for awhile, at least until it happens again, and see if there's some difference in the log comparing a time that a torrent completes as expected and a time that a torrent doesn't finish properly?  Use the logmask parameter in utserver.conf, setting it to 0xffffffff to set this up, or better, set to 0xf7bfffff to remove some noise from what are probably unrelated services like UPnP and the HTTP server.

Link to comment
Share on other sites

That didn't work very well. With logmask set to 0xf7bfffff the server crashes after 5-10 minutes. This is all I get in the log after the normal startup entries:

 

[20140416 20:23:12] recvfrom ERROR: 11

[20140416 20:23:12] UPnP: Device error "http://192.168.1.159:8060/": (-2) 

[20140416 20:23:12] recvfrom ERROR: 11

[20140416 20:23:13] recvfrom ERROR: 11

[20140416 20:23:13] recvfrom ERROR: 11

[20140416 20:23:13] recvfrom ERROR: 11

 

steve

Link to comment
Share on other sites

I created a cron job to watch the list using wget. If i wait the job does seem to always go to finished, but it sticks at 100% seeding for a random amount of time. Not every job, just these odd ones. I thought maybe this had to do with my default seed ratio, but I've tried different settings and it doesn't seem to correlate. As a test is there a way to tell it to stop seeding once the I'm at 100%? For example, if I set the "Minimum Ratio (%)" to zero what is that supposed to do? I tried that and I tried a value of 1% but the circumstance still happens with either of these values.

 

steve

Link to comment
Share on other sites

Does this occur always with the same torrents, or does this occur independent of the specific torrent?

Not sure, I'll start one of these over and let you know. I don't think I mentioned this, but when this happens the completed script gets called and for some jobs my script is deleting the torrent. If it happens to be one of these odd ones then the files are left in the busy folder. I changed my script to check for the Finished state to stop that and log a message so I know when it is happening now. Since the completion script is being called I think that means the software thought it was done, but it really hadn't moved the file to the finish folder and marked it finished for some reason.

 

thanks

Link to comment
Share on other sites

Thanks for the screenshot.  What is shown doesn't look right.  I would expect for a seeding torrent to see all files at 100% unless they are excluded from download.  Maybe there is an edge case if the download is being blocked due to scheduling (in a seeding-only period).

 

I haven't had time to look into this.  I tried it just now on a multi-file Internet Archive (AboutBan1935) torrent and it behaved correctly (status didn't change to 'Seeding' until all files had been 100% downloaded).  I might need to use certain torrents.

Link to comment
Share on other sites

PM'd you with a repeatable case. Very strange. I watched it a couple of times. It's clipping along slowly, then someone starts feeding it quickly and after a few seconds it jumps to seeding even though many files are incomplete. Not sure if the sudden rate change had something to do with it or that's just a coincidence but it seemed to happen that way each time.

 

Forgot to mention my utserver version prints:

 

330B (30470) 2014-01-14 09:10:15 -0800

 

and I'm running it on ubuntu 12.04LTS 64 bit, it's up to date.

 

steve

Link to comment
Share on other sites

My utserver has a bunch of "PIECE ### FAILED HASH CHECK" entries in it for this torrent. Half baked theory: We do the accounting for pieces, but when it fails a hash check we don't discount it. So at some point we have a count which indicates all the pieces were received even though a bunch were thrown away.

 

steve

Link to comment
Share on other sites

  • 2 weeks later...

I had read your PM, so not sure what you used to determine that I had not read it; maybe the forum has a place to look at PMs, and I didn't use that since it gets delivered to me via email.

 

Have you tried downloading the AboutBan1935 torrent from IA and have you seen the problem with that torrent?  I'm curious if you are seeing the problem with a torrent for which I'm not seeing the problem.  Hopefully, we can identify a torrent that is unencumbered by legal issues and also reproduces the problem, so that the greatest number of participants can work on it.

Link to comment
Share on other sites

Sorry I was looking at the messages link under my name and that shows read/unread but probably doesn't account for email :-).

 

No one was seeding that particular torrent for some reason but this one from the internet archive repro'd the behavior:

 

https://archive.org/details/TomAndJerryInANightBeforeChristmas

 

And there were no errors in my utserver.log during the transfer. It was over 94% when it suddenly changed to seeding and there was one file still at 94%.

 

This one did eventually finish all the files and now it just sits there saying seeding. The Finish script was called and that script will remove the torrent if it is Finished at 100%. My log printed out this:

 

Skipping 'TomAndJerryInANightBeforeChristmas' - 100% (Seeding)

 

It's still in this state a half hour later, but this is maybe normal because it hasn't hit the seed ratio yet?

 

steve

Link to comment
Share on other sites

I didn't reproduce what you saw with this torrent.  There's a gigabit Internet connection here so bits fly by pretty fast, but I was able to see enough detail.  I saw the web UI show the torrent change to "Seeding" at the same time that all the files went to 100%.  I performed this download twice.

 

I'm curious what you have in your utserver.conf to see if I could more closely match your setup.

Link to comment
Share on other sites

$ grep -v ^# utserver.conf | grep -v ^$

dir_active: "/media/sf_BitTorrent/Busy"

dir_completed: "/media/sf_BitTorrent/Completed"

finish_cmd: "/media/sf_BitTorrent/cleanup_utorrent.sh"

max_ul_rate: 150

seed_ratio: 150

 

Is there a way to dump my settings.dat? I do wonder if there is an advanced setting I tweaked or something. I'm definitely a tweaker :-). I suppose I could delete setttings.dat and see what happens if you want.

 

Just in case there is some wierd library issue here's ldd:

 


$ ldd utserver

        linux-vdso.so.1 =>  (0x00007fffa2b6f000)

        libssl.so.1.0.0 => /lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007f63e7e56000)

        libcrypto.so.1.0.0 => /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f63e7a7b000)

        libresolv.so.2 => /lib/x86_64-linux-gnu/libresolv.so.2 (0x00007f63e785e000)

        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f63e7641000)

        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007f63e7439000)

        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f63e713c000)

        libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f63e6f26000)

        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f63e6b66000)

        /lib64/ld-linux-x86-64.so.2 (0x00007f63e80c6000)

        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f63e6961000)

        libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007f63e674a000)

 


-steve
Link to comment
Share on other sites

Well, good news, bad news. I moved settings.* out of the utserver directory and restarted. After having done this the behavior is better. When it goes to seeding all the files are 100%. However, the finish script still gets called at seeding instead of when finished. I've had a script in place for a long time to remove when Finished (after seeding). On the prior server year old utserver version this script always worked.

 

So while better it's still different than it used to be. Was the intention that the "script run when finished" is after 100% files are received or when the state goes to Finished? Let's call this the "early finish script problem".

 

Do you want me to try to figure out what setting I had set in the old settings file that causes the torrent to go to seeding before all the files are received? Let's call this the "early seeding problem". Can I diff a settings.dat file?

 

steve

Link to comment
Share on other sites

[

Well, good news, bad news. I moved settings.* out of the utserver directory and restarted. After having done this the behavior is better. When it goes to seeding all the files are 100%. However, the finish script still gets called at seeding instead of when finished. I've had a script in place for a long time to remove when Finished (after seeding). On the prior server year old utserver version this script always worked.

So while better it's still different than it used to be. Was the intention that the "script run when finished" is after 100% files are received or when the state goes to Finished? Let's call this the "early finish script problem".

If you are moving the torrent data files from an active to a completed directory (and they are on different devices), the move will complete before finish is called.

I'll look into this more.

 

Do you want me to try to figure out what setting I had set in the old settings file that causes the torrent to go to seeding before all the files are received? Let's call this the "early seeding problem". Can I diff a settings.dat file?

That would be interesting if you have the time. settings.dat contains some binary data, so diff may not play well with it. I believe there are bencoded file browsers available on the web for download.

Link to comment
Share on other sites

  • 2 weeks later...

Haven't had a chance to look at either of these problems further, but I switched to using the state change script instead of the finished script. That plus the removal of my settings.dat files has found me a combination that seems to work without error. That is, when a download finishes seeding, I get an invocation of the script that can then remove the file. I also get a nice log of all state changes. Here's the script:

#!/bin/bashstatus=${1}torrent=${2}hash=${3}user="xxxx"password="yyyy"server="192.168.1.200:80"this_file=${0##*/}log=${0%/*}/${this_file%%.*}.logcookie=${hash}.txt# Get the auth token.WGET_NEED_COOKIE="wget --save-cookies ${cookie} --keep-session-cookies"WGET_HAVE_COOKIE="wget --load-cookies ${cookie} --http-user=$user --http-password=$password"resp1=`$WGET_NEED_COOKIE --http-user=$user --http-password=$password -q -O - http://$server/gui/token.html`token=`echo -e "$resp1" | awk -F'[<>]' '/<div[^>]*id=[\"'"'"']*token[\"'"'"'][^>]*>([^<]*)<\/div>/ { print $5  }'`#Remove the torrent if it finished or had an errorentry="`date +%x\ %X` \"${status}\" \"${torrent}\" ${hash}"if [[ "$status" == "Finished" || "$status" ==  "Error"* ]]; then    resp3=`$WGET_HAVE_COOKIE -q -O - http://$server/gui/?action=remove\&token=${token}\&hash=${hash}`    if [[ "$resp3" == "" ]]; then        resp3="ERROR"    fi    entry="${entry} RESP=${resp3}"fiecho "${entry}" | tee -a ${log}rm -f ${cookie}
Link to comment
Share on other sites

Archived

This topic is now archived and is closed to further replies.

×
×
  • Create New...