search

sabnzbd / sabnzbd

SABnzbd - The automated Usenet download tool
http://sabnzbd.org
Other
2.25k stars 338 forks source link

Downloads halting until manually paused and resumed #616

Closed rastating closed 8 years ago

rastating commented 8 years ago

Branch: develop Commit: 8e0846a682b101e8d7fd26c95e467598f5bd5d3c

As per the title, seemingly at random, I have been seeing downloads halting and not budging until such time as I manually pause them and resume. I've had a look through the log file, and can't see anything odd looking.

The log below illustrates the point at which the final download in my list halted until 22:30 when I paused and resumed it:

2016-07-07 14:12:45,239::INFO::[newsunpack:258] Unrar finished on /mnt/<USERNAME>/incomplete/download_name
2016-07-07 14:12:45,242::INFO::[postproc:371] unpack_magic finished on download_name
2016-07-07 14:12:45,253::INFO::[postproc:822] Collapsing /mnt/<USERNAME>/complete/download_name
2016-07-07 14:12:45,819::INFO::[postproc:564] Cleaning up download_name (keep_basic=False)
2016-07-07 14:12:45,820::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_iF7XHW removed
2016-07-07 14:12:45,821::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_MS3o6V removed
2016-07-07 14:12:45,822::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_RkW_XC removed
2016-07-07 14:12:45,822::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_TsaNzV removed
2016-07-07 14:12:45,823::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_BLph35 removed
2016-07-07 14:12:45,824::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_Kbo6jC removed
2016-07-07 14:12:45,824::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_V3Jr1K removed
2016-07-07 14:12:45,825::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_Z5sBGu removed
2016-07-07 14:12:45,825::INFO::[__init__:936] /mnt/<USERNAME>/incomplete/download_name/__ADMIN__/SABnzbd_nzf_IdJPx2 removed
2016-07-07 14:12:45,835::INFO::[postproc:83] Saving postproc queue
2016-07-07 14:12:45,835::INFO::[__init__:945] Saving data for postproc2.sab in /home/<USERNAME>/.<USERNAME>/admin/postproc2.sab
2016-07-07 14:12:45,835::INFO::[downloader:279] Post-processing finished, resuming download
2016-07-07 14:17:29,942::INFO::[downloader:735] Thread 11@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:30,716::INFO::[downloader:735] Thread 12@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:32,134::INFO::[downloader:735] Thread 14@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:33,344::INFO::[downloader:735] Thread 8@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:33,822::INFO::[downloader:735] Thread 4@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:34,290::INFO::[downloader:735] Thread 16@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:38,677::INFO::[downloader:735] Thread 1@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:39,349::INFO::[downloader:735] Thread 5@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:43,494::INFO::[downloader:735] Thread 3@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:43,545::INFO::[downloader:735] Thread 18@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:45,286::INFO::[downloader:735] Thread 2@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:46,900::INFO::[downloader:735] Thread 20@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:47,803::INFO::[downloader:735] Thread 7@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:49,367::INFO::[downloader:735] Thread 19@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:49,733::INFO::[downloader:735] Thread 9@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:50,724::INFO::[downloader:735] Thread 6@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:54,001::INFO::[downloader:735] Thread 17@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:54,903::INFO::[downloader:735] Thread 10@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:17:57,177::INFO::[downloader:735] Thread 13@ssl-eu.astraweb.com: server closed connection
2016-07-07 14:18:08,402::INFO::[downloader:735] Thread 15@ssl-eu.astraweb.com: server closed connection

As you can see, it finishes one download, then afterwards all the connections seem to close (seemingly from the newsgroup's side). It looks as if once the connection is closed by the server it's not connecting again until such time as a pause/resume is done.

Unfortunately, I can't provide any steps to replicate it every time, so can't offer any more advice as to what it may be :(

rastating commented 8 years ago

Just seen it happen again with only one download in the queue this time, with the same messages in the log regarding connection closures:

2016-07-07 23:01:01,870::INFO::[decoder:217] Prospectively added 32 repair blocks to download_name
2016-07-07 23:01:01,871::INFO::[decoder:217] Prospectively added 64 repair blocks to download_name
2016-07-07 23:01:01,905::INFO::[__init__:945] Saving data for totals10.sab in /home/<USERNAME>/.<USERNAME>/admin/totals10.sab
2016-07-07 23:01:01,906::INFO::[assembler:88] Decoding /mnt/<USERNAME>/incomplete/download_name/<HIDE-HASH>848.part21.rar yenc
2016-07-07 23:01:01,925::INFO::[assembler:179] <Article: article=Part9of137.<HIDE-HASH>9A08B70@1438674113.local, bytes=398768, partnum=9, art_id=None> missing
2016-07-07 23:01:02,026::INFO::[assembler:179] <Article: article=Part47of137.<HIDE-HASH>DD10DB6@1438674113.local, bytes=398503, partnum=47, art_id=None> missing
2016-07-07 23:01:02,038::INFO::[assembler:179] <Article: article=Part52of137.<HIDE-HASH>2A01327@1438674113.local, bytes=398716, partnum=52, art_id=None> missing
2016-07-07 23:01:02,112::INFO::[assembler:179] <Article: article=Part80of137.<HIDE-HASH>ECA9D85@1438674113.local, bytes=398561, partnum=80, art_id=None> missing
2016-07-07 23:01:02,211::INFO::[assembler:179] <Article: article=Part118of137.<HIDE-HASH>65482C1@1438674113.local, bytes=398575, partnum=118, art_id=None> missing
2016-07-07 23:05:06,622::INFO::[downloader:735] Thread 14@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:11,786::INFO::[downloader:735] Thread 18@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:12,765::INFO::[downloader:735] Thread 16@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:13,091::INFO::[downloader:735] Thread 13@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:13,892::INFO::[downloader:735] Thread 17@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:16,342::INFO::[downloader:735] Thread 8@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:17,615::INFO::[downloader:735] Thread 9@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:17,989::INFO::[downloader:735] Thread 15@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:18,539::INFO::[downloader:735] Thread 1@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:19,746::INFO::[downloader:735] Thread 19@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:19,953::INFO::[downloader:735] Thread 2@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:25,085::INFO::[downloader:735] Thread 4@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:25,478::INFO::[downloader:735] Thread 5@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:28,936::INFO::[downloader:735] Thread 11@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:31,742::INFO::[downloader:735] Thread 20@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:33,422::INFO::[downloader:735] Thread 3@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:38,209::INFO::[downloader:735] Thread 7@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:38,700::INFO::[downloader:735] Thread 12@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:05:38,966::INFO::[downloader:735] Thread 6@ssl-eu.astraweb.com: server closed connection
2016-07-07 23:06:10,132::INFO::[downloader:735] Thread 10@ssl-eu.astraweb.com: server closed connection
Safihre commented 8 years ago

You're develop branch is outdated, I added a fix for this a few days ago.

Can you git pull and see if it still happens after that?

labrys commented 8 years ago

@Safihre Is this also related to a bunch of files (ones that wont complete) being stuck in queue? I have a bunch with missing parts that have just been chilling at the top of my queue for quite a while. If they're going to fail I'd rather them just fail so that Medusa can process it as failed and snatch a different one.

Safihre commented 8 years ago

@labrys do they continue if you pause and unpause them?

labrys commented 8 years ago

No they do not.

Safihre commented 8 years ago

I'd suggest you set them to Priority > Stop, this way they will be post-processed and possibly more blocks will be fetched. This might be from older bugs.

Let us know if it happens again to newly added NZB's after the latest fixes.

labrys commented 8 years ago

Will do, I'll try it later today and let you know.

rastating commented 8 years ago

@Safihre - just pulled the latest version, I'll queue up an hour or two's worth of stuff and see if I can replicate

rastating commented 8 years ago

@Safihre - tested with ~70GB of data and didn't manage to replicate it, so looks like your fix did the trick :+1:

labrys commented 8 years ago

@Safihre Setting priority to stop fixed the majority of the .nzbs by allowing them to fail properly. The rest have been re-added to the queue but as my backlog search for Medusa hit today, the api limit on those has been hit. I consider my issue resolved as well. If there are any further problems with it, I'll open an issue.