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

sab 2.3.0RC1 -- Error importing - causing sab to crash #1034

Closed
thezoggy opened this Issue Sep 18, 2017 · 31 comments

Comments

Projects
None yet
4 participants
@thezoggy
Copy link
Contributor

thezoggy commented Sep 18, 2017

friend is seeing sab crash over and over since updating sab to 2.3.0RC1 (and sabyenc).. not seeing a trace error but right before it crashes we see:

2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1137] sabnzbdplus-2.3.0RC1 (rev=63e6d45bb1a225ce4c89dc496a5f57564eee17a8)
2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1138] Full executable path = /usr/bin/sabnzbdplus
2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1148] Platform = posix
2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1149] Python-version = 2.7.12 (default, Nov 19 2016, 06:48:10) 
[GCC 5.4.0 20160609]
2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1150] Arguments = /usr/bin/sabnzbdplus --daemon --pidfile /var/run/sabnzbdplus/pid
2017-09-18 16:48:17,188::INFO::[sabnzbdplus:1155] Preferred encoding = UTF-8
2017-09-18 16:48:17,189::INFO::[sabnzbdplus:1165] SSL version = OpenSSL 1.0.2g  1 Mar 2016
...
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:392] SABYenc module (v3.0.2)... found!
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:409] Cryptography module (v1.2.3)... found!
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:414] par2 binary... found (/usr/bin/par2)
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:424] UNRAR binary... found (/usr/bin/unrar)
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:432] UNRAR binary version 5.30
2017-09-18 16:48:17,517::INFO::[sabnzbdplus:437] unzip binary... found (/usr/bin/unzip)
2017-09-18 16:48:17,518::INFO::[sabnzbdplus:442] 7za binary... found (/usr/bin/7za)
2017-09-18 16:48:17,518::INFO::[sabnzbdplus:448] nice binary... found (/usr/bin/nice)
2017-09-18 16:48:17,518::INFO::[sabnzbdplus:452] ionice binary... found (/usr/bin/ionice)
2017-09-18 16:48:17,520::INFO::[sabnzbdplus:1368] Starting web-interface on 0.0.0.0:8800
...
2017-09-18 16:32:58,180::DEBUG::[nzbstuff:1451] Skipping existing file <HASH>622bebac96470cb.par2
2017-09-18 16:32:58,180::DEBUG::[nzbstuff:1451] Skipping existing file <HASH>622bebac96470cb.part01.rar
2017-09-18 16:32:58,180::DEBUG::[nzbstuff:1451] Skipping existing file <HASH>622bebac96470cb.part02.rar
2017-09-18 16:32:58,180::DEBUG::[nzbstuff:1451] Skipping existing file <HASH>622bebac96470cb.part03.rar
2017-09-18 16:32:58,180::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [05/41] - "<HASH>622bebac96470cb.part04.rar" yEnc (1/21)
2017-09-18 16:32:58,181::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_J5V_PW missing
2017-09-18 16:32:58,181::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part04.rar, type=None>
2017-09-18 16:32:58,181::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part04.rar, type=None>
2017-09-18 16:32:58,181::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [06/41] - "<HASH>622bebac96470cb.part05.rar" yEnc (1/21)
2017-09-18 16:32:58,181::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_NjwUZB missing
2017-09-18 16:32:58,181::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part05.rar, type=None>
2017-09-18 16:32:58,182::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part05.rar, type=None>
2017-09-18 16:32:58,182::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [07/41] - "<HASH>622bebac96470cb.part06.rar" yEnc (1/21)
2017-09-18 16:32:58,182::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_5L1Ocl missing
2017-09-18 16:32:58,182::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part06.rar, type=None>
2017-09-18 16:32:58,182::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part06.rar, type=None>
2017-09-18 16:32:58,182::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [08/41] - "<HASH>622bebac96470cb.part07.rar" yEnc (1/21)
2017-09-18 16:32:58,182::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_qJF9yy missing
2017-09-18 16:32:58,183::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part07.rar, type=None>
2017-09-18 16:32:58,183::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part07.rar, type=None>
2017-09-18 16:32:58,183::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [09/41] - "<HASH>622bebac96470cb.part08.rar" yEnc (1/21)
2017-09-18 16:32:58,183::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_ORGYLU missing
2017-09-18 16:32:58,183::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part08.rar, type=None>
2017-09-18 16:32:58,183::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part08.rar, type=None>
2017-09-18 16:32:58,183::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [10/41] - "<HASH>622bebac96470cb.part09.rar" yEnc (1/21)
2017-09-18 16:32:58,184::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_9coMde missing
2017-09-18 16:32:58,184::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=<HASH>622bebac96470cb.part09.rar, type=None>
2017-09-18 16:32:58,184::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=<HASH>622bebac96470cb.part09.rar, type=None>
2017-09-18 16:32:58,184::DEBUG::[nzbstuff:276] Finishing import on <HASH>622bebac96470cb [11/41] - "<HASH>622bebac96470cb.part10.rar" yEnc (1/21)
2017-09-18 16:32:58,184::INFO::[__init__:909] /home/<USERNAME>/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_9GuGJg missing
...

had a hard time looking through logs, moved logs out and started sab up and waited for it to crash..

...
2017-09-18 16:42:14,388::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=97bacab331d0c42b218b5bd7a622bebac96470cb.vol63+03.par2, type=None>
2017-09-18 16:42:14,388::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=97bacab331d0c42b218b5bd7a622bebac96470cb.vol63+03.par2, type=None>
2017-09-18 16:42:46,329::INFO::[__init__:1058] Restarting because of crashed downloader
@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 18, 2017

looking at sabnzbd.error.log:

Exception in thread HTTPServer Thread-9:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 504, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/share/sabnzbdplus/cherrypy/process/servers.py", line 75, in _start_http_thread
    self.httpserver.start()
  File "/usr/share/sabnzbdplus/cherrypy/wsgiserver/__init__.py", line 1644, in start
    raise socket.error, msg
error: [Errno 99] Cannot assign requested address

/usr/share/sabnzbdplus/sabnzbd/newsunpack.py:1666: UnicodeWarning: Unicode equal comparison failed to convert both arguments to Unicode - interpreting them as being unequal
  if file == nzf.filename:
/usr/share/sabnzbdplus/sabnzbd/newsunpack.py:1730: UnicodeWarning: Unicode equal comparison failed to convert both arguments to Unicode - interpreting them as being unequal
  if file == nzf.filename:
Exception in thread Thread-4:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/decoder.py", line 88, in run
    nzf = article.nzf
AttributeError: 'NoneType' object has no attribute 'nzf'

Exception in thread Thread-3:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/downloader.py", line 745, in run
    server.busy_threads.remove(nw)
ValueError: list.remove(x): x not in list

Exception in thread Thread-6:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/assembler.py", line 143, in run
    nzo.add_to_direct_unpacker(nzf)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbstuff.py", line 1272, in add_to_direct_unpacker
    self.direct_unpacker.add(nzf)
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 109, in add
    test_disk_performance()
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 387, in test_disk_performance
    config.save_config()
NameError: global name 'config' is not defined

Exception in thread Thread-6:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/assembler.py", line 143, in run
    nzo.add_to_direct_unpacker(nzf)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbstuff.py", line 1272, in add_to_direct_unpacker
    self.direct_unpacker.add(nzf)
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 135, in add
    self.start()
  File "/usr/lib/python2.7/threading.py", line 730, in start
    raise RuntimeError("threads can only be started once")
RuntimeError: threads can only be started once

Exception in thread Thread-348:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 204, in run
    self.create_unrar_instance()
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 301, in create_unrar_instance
    rarfile_path = os.path.join(self.nzo.downpath, self.rarfile_nzf.filename)
AttributeError: 'bool' object has no attribute 'filename'
@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 18, 2017

also to note, the warning page has just a ton of entries for:
Error importing
Article DB empty

which doesnt tell you anything.. really should log what nzb is sab trying to import.. so the user can do something

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 19, 2017

deleted the queue finally got sab to stop crashing.
tried one of the nzb again and it worked fine.
I noticed that a few of the nzb that were failing to import already were in the queue, so duplicate nzb causing it to freak out?

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 19, 2017

Ah, so it can also happen on non-Windows.. Must be something else then.

also to note, the warning page has just a ton of entries for:

Error importing
Article DB empty

In Glitter they display correctly, maybe not in Smpl/Plush.

Safihre added a commit that referenced this issue Sep 19, 2017

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 19, 2017

@thezoggy Can you send me his logs? Maybe we can find why the files were deleted, it should be in the log.

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 19, 2017

this was in glitter, and running on ubuntu 16.x, sending logs now

Safihre added a commit that referenced this issue Sep 19, 2017

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 19, 2017

Oops you are right, I accidentally removed the HTML-conversion from Alpha > RC. Will be fixed.

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 19, 2017

emailed you the logs.

to note per sabnzbd.log:

2017-09-18 16:30:20,487::ERROR::[database:204] SQL Commit Failed, see log
2017-09-18 16:30:20,488::INFO::[database:205] Traceback: 
Traceback (most recent call last):
  File "/usr/share/sabnzbdplus/sabnzbd/database.py", line 202, in save
    self.con.commit()
OperationalError: database is locked
2017-09-18 16:30:20,490::INFO::[database:283] Added job The.Amazing.Race.AU.S02E04.PDTV.x264-RTA to history

but looks like it just kept on going on.. then you see the 97bacab331d0c42b218b5bd7a622bebac96470cb job go to crap which then triggered sab to crash.. then on restart it tries again.. rinse and repeat.

2017-09-18 16:30:50,741::DEBUG::[downloader:718] Thread 8@eunews.blocknews.net: Article 53e08f5d$0$17405$c3e8da3$2bd0d6bf@news.astraweb.com missing (error=430)
2017-09-18 16:30:50,742::DEBUG::[nzbstuff:276] Finishing import on 97bacab331d0c42b218b5bd7a622bebac96470cb [01/41] - "97bacab331d0c42b218b5bd7a622bebac96470cb.par2" yEnc (1/1)
2017-09-18 16:30:50,742::INFO::[__init__:909] /home/keith/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_q34qnf missing
2017-09-18 16:30:50,742::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=97bacab331d0c42b218b5bd7a622bebac96470cb.par2, type=None>
2017-09-18 16:30:50,742::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=97bacab331d0c42b218b5bd7a622bebac96470cb.par2, type=None>
2017-09-18 16:30:50,742::DEBUG::[nzbstuff:276] Finishing import on 97bacab331d0c42b218b5bd7a622bebac96470cb [02/41] - "97bacab331d0c42b218b5bd7a622bebac96470cb.part01.rar" yEnc (1/21)
2017-09-18 16:30:50,743::INFO::[__init__:909] /home/keith/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_NqYSmK missing

Safihre added a commit that referenced this issue Sep 19, 2017

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 19, 2017

Ok I fixed that a locked DB will not orphan a job (it wasn't retried).

But what goes wrong here after that, I have no clue.
For example this file SABnzbd_nzf_iJ6mOQ: it get's added as part32.rar, then it gets removed during the retry of the orphan, but then pops up again but SAB thinks it belongs to the .sfv?! But the .sfv was added after the retry as SABnzbd_nzf_9kzSq9.
I'm lost.

2017-09-18 16:29:23,410::INFO::[nzbstuff:514] File 97bacab331d0c42b218b5bd7a622bebac96470cb [33/41] - "97bacab331d0c42b218b5bd7a622bebac96470cb.part32.rar" yEnc (1/8) added to queue
2017-09-18 16:29:23,410::DEBUG::[__init__:877] Saving data for SABnzbd_nzf_iJ6mOQ in /home/xxxxxx/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__

2017-09-18 16:29:39,809::DEBUG::[misc:1091] Removing file /home/xxxxxx/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_iJ6mOQ

2017-09-18 16:30:50,760::DEBUG::[nzbstuff:276] Finishing import on 97bacab331d0c42b218b5bd7a622bebac96470cb [34/41] - "97bacab331d0c42b218b5bd7a622bebac96470cb.sfv" yEnc (1/1)
2017-09-18 16:30:50,760::INFO::[__init__:909] /home/xxxxxx/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__/SABnzbd_nzf_iJ6mOQ missing

--
2017-09-18 16:29:39,861::INFO::[nzbstuff:514] File 97bacab331d0c42b218b5bd7a622bebac96470cb [34/41] - "97bacab331d0c42b218b5bd7a622bebac96470cb.sfv" yEnc (1/1) added to queue
2017-09-18 16:29:39,862::DEBUG::[__init__:877] Saving data for SABnzbd_nzf_9kzSq9 in /home/xxxxxx/tmp/downloads/incomplete/nzb/The.Amazing.Race.Canada.S02E05.HDTV.x264-2HD-Obfuscated/__ADMIN__

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 20, 2017

Adding this to #952. Added now that the job wil be paused in the hope we can investigate more.

@Safihre Safihre closed this Sep 20, 2017

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 21, 2017

ty

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 23, 2017

now on 2.3.0 just saw similar thing. sonarr sent ton of nzb's to sab.. sab started processing. at some point sab went to crap with speed/restarting helped but then saw the wave of warning/errors for article/import issues.. sab restarting. logs have already rolled because of the sheer amount of noise produced by directunpacker/assembler/etc on debug. but looking in the sabnzbd.error.log we see the same stuff from before:

Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 212, in run
    self.create_unrar_instance()
  File "/usr/share/sabnzbdplus/sabnzbd/directunpacker.py", line 311, in create_unrar_instance
    rarfile_path = os.path.join(self.nzo.downpath, self.rarfile_nzf.filename)
AttributeError: 'bool' object has no attribute 'filename'

Exception in thread Thread-5:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/downloader.py", line 465, in run
    article = sabnzbd.nzbqueue.NzbQueue.do.get_article(server, self.servers)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbqueue.py", line 728, in get_article
    article = nzo.get_article(server, servers)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbstuff.py", line 1476, in get_article
    nzf.completed = True
AttributeError: can't set attribute

Exception in thread Thread-5:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/share/sabnzbdplus/sabnzbd/downloader.py", line 465, in run
    article = sabnzbd.nzbqueue.NzbQueue.do.get_article(server, self.servers)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbqueue.py", line 728, in get_article
    article = nzo.get_article(server, servers)
  File "/usr/share/sabnzbdplus/sabnzbd/nzbstuff.py", line 1476, in get_article
    nzf.completed = True
AttributeError: can't set attribute

going to just turn off directunpacker for now on this setup

@Safihre Safihre reopened this Sep 23, 2017

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 23, 2017

just sent you logs from this latest instance

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 24, 2017

This is strange, it seems there are 2 NZO's pointing to the same directory:

2017-09-23 12:28:17,287::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_RP4fCH in /home/xxxxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__
2017-09-23 12:28:17,653::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_jXGj7b in /home/xxxxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__

Do you maybe also happen to have the older logs from the logs directory? Then we can check where these 2 files were created.

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Sep 25, 2017

just sent you the older log files. looks like everything you want is in sabnzbd.log.2

2017-09-23 12:17:09,666::DEBUG::[__init__:913] Loading data for SABnzbd_nzo_RP4fCH from /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__/SABnzbd_nzo_RP4fCH
2017-09-23 12:17:09,667::DEBUG::[__init__:913] Loading data for SABnzbd_nzo_jXGj7b from /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__/SABnzbd_nzo_jXGj7b

2017-09-23 12:03:32,684::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_RP4fCH in /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__

wonder if this is the culprit..

2017-09-23 12:03:51,072::INFO::[interface:1230] Re-adding orphaned job /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE
2017-09-23 12:03:51,073::INFO::[__init__:909] /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__/__verified__ missing
2017-09-23 12:03:51,076::DEBUG::[nzbqueue:216] Repair job Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE by reparsing stored NZB
2017-09-23 12:03:51,076::INFO::[__init__:670] Adding Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE.nzb.gz

which then you see the old job get nuked:

2017-09-23 12:03:51,082::DEBUG::[misc:1091] Removing file /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__/SABnzbd_nzo_RP4fCH

2017-09-23 12:03:51,120::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_jXGj7b in /home/xxx/tmp/downloads/incomplete/nzb/Everybody.Loves.Raymond.S06E20.A.Vote.for.Debra.x264.DVDRip-BUYMORE/__ADMIN__

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 28, 2017

I cannot really find out what caused the job to go orphaned in the first place.. Bit strange.

Safihre added a commit that referenced this issue Sep 28, 2017

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Sep 28, 2017

I think it's the sorting of the Queue which causes some form of race condition because I removed the NZBQUEUE_LOCK, @labrys also reported it happening when he was sorting the queue.

Safihre added a commit that referenced this issue Sep 28, 2017

Re-introduce NZBQUEUE_LOCK
There seems to be no performance impact.

Linked #1034 and #952 

Reverts partially 02ebb97
@mgaulton

This comment has been minimized.

Copy link

mgaulton commented Sep 29, 2017

I've been noticing crashes as well. I've also see "too many open files" occuring in the past week. SAB and fail2ban seem to be the only things affected, but i haven't been able to pin it down to anything specific.
My file limits are up to 200k and still seeing it, which i find odd.
latest git pull, opensuse 42.3, python 2.7.13

queue repair had no apparent effect.
moving all nzbs, deleting the queue temp files and then reimporting all the nzbds, no result.

@labrys

This comment has been minimized.

Copy link

labrys commented Sep 29, 2017

Since fall season is started I will likely see these again soon. I'll monitor and post relevant data when I get a chance.

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Oct 3, 2017

there was a blip last week but since then so far so good...
sabb

@labrys

This comment has been minimized.

Copy link

labrys commented Oct 3, 2017

image

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Oct 5, 2017

@thezoggy What was up with that job with all the 'unable to find xxx.2.rar'?
Something that needs to be fixed?

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Oct 5, 2017

sadly by the time I saw those errors the logs didnt go far enough back, wanted to share what I saw in case others see the same.. I just tried the nzb myself and it worked fine. So not sure.

@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Oct 8, 2017

@labrys @thezoggy If no Failed to import errors occur anymore this week on 2.3.1Beta1 I'll consider this and #952 fixed.

@thezoggy

This comment has been minimized.

Copy link
Contributor

thezoggy commented Oct 8, 2017

updating now.. will let you know

@labrys

This comment has been minimized.

Copy link

labrys commented Oct 8, 2017

Same.

@labrys

This comment has been minimized.

Copy link

labrys commented Oct 10, 2017

2017-10-09 18:16:00,815::ERROR::[nzbstuff:1476] Error importing <NzbFile: filename=[PRiVATE] \ff93a77ac8\::d8c85509e05bfb.71a8b726380d5f228e2544734e40af.73460bf2::/f491e0aabacb/ [newzNZB] [2/36] - yEnc  50000000 (1/70), type=None>
@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Oct 10, 2017

That's a crazy filename.. Only once?
To fix this I need Debug logs that span from adding the job to when it fails, but I guess in your case that might not all be part of the same logging (too many downloads) ?

@labrys

This comment has been minimized.

Copy link

labrys commented Oct 10, 2017

No there was actually a ton of those in the log, I only pasted the single instance. I'll look to see if i still have it in my logs.

Safihre added a commit that referenced this issue Oct 11, 2017

Safihre added a commit that referenced this issue Oct 11, 2017

@mgaulton

This comment has been minimized.

Copy link

mgaulton commented Oct 12, 2017

So i'm updated to latest on master, noticed i'm still getting crashed downloaders.
last night, i nuked everything except the ini file from my config stash and reimported all the nzbs.
notice it had come up, sorted by newest to oldest, and boom, it was down again, this is was was in the log around the time

2017-10-12 13:23:40,435::DEBUG::[nzbstuff:1451] Skipping existing file 66ef2139013741408bd97ea5ac6dc6d7.part04.rar
2017-10-12 13:23:40,435::DEBUG::[nzbstuff:1451] Skipping existing file 66ef2139013741408bd97ea5ac6dc6d7.part05.rar
2017-10-12 13:23:40,435::DEBUG::[nzbstuff:276] Finishing import on 66ef2139013741408bd97ea5ac6dc6d7 [7/60] "66ef2139013741408bd97ea5ac6dc6d7.part06.rar" yEnc (1/20)
2017-10-12 13:23:40,435::INFO::[__init__:909] /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__/SABnzbd_nzf_Za2aqh missing
2017-10-12 13:23:40,435::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part06.rar, type=None>
2017-10-12 13:23:40,435::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part06.rar, type=None>
2017-10-12 13:23:40,435::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_Ccxocy in /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__
2017-10-12 13:23:40,448::DEBUG::[nzbstuff:276] Finishing import on 66ef2139013741408bd97ea5ac6dc6d7 [8/60] "66ef2139013741408bd97ea5ac6dc6d7.part07.rar" yEnc (1/20)
2017-10-12 13:23:40,452::INFO::[__init__:909] /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__/SABnzbd_nzf_ZGJQFb missing
2017-10-12 13:23:40,452::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part07.rar, type=None>
2017-10-12 13:23:40,452::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part07.rar, type=None>
2017-10-12 13:23:40,453::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_Ccxocy in /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__
2017-10-12 13:23:40,490::DEBUG::[nzbstuff:276] Finishing import on 66ef2139013741408bd97ea5ac6dc6d7 [9/60] "66ef2139013741408bd97ea5ac6dc6d7.part08.rar" yEnc (1/20)
2017-10-12 13:23:40,490::INFO::[__init__:909] /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__/SABnzbd_nzf_xrAwvV missing
2017-10-12 13:23:40,491::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part08.rar, type=None>
2017-10-12 13:23:40,491::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part08.rar, type=None>
2017-10-12 13:23:40,491::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_Ccxocy in /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__
2017-10-12 13:23:40,544::DEBUG::[nzbstuff:276] Finishing import on 66ef2139013741408bd97ea5ac6dc6d7 [10/60] "66ef2139013741408bd97ea5ac6dc6d7.part09.rar" yEnc (1/20)
2017-10-12 13:23:40,544::INFO::[__init__:909] /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__/SABnzbd_nzf_S5shzW missing
2017-10-12 13:23:40,544::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part09.rar, type=None>
2017-10-12 13:23:40,544::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part09.rar, type=None>
2017-10-12 13:23:40,544::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_Ccxocy in /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__
2017-10-12 13:23:40,578::DEBUG::[nzbstuff:276] Finishing import on 66ef2139013741408bd97ea5ac6dc6d7 [11/60] "66ef2139013741408bd97ea5ac6dc6d7.part10.rar" yEnc (1/20)
2017-10-12 13:23:40,578::INFO::[__init__:909] /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__/SABnzbd_nzf_cjI3xJ missing
2017-10-12 13:23:40,578::WARNING::[nzbstuff:295] Article DB empty <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part10.rar, type=None>
2017-10-12 13:23:40,578::ERROR::[nzbstuff:1462] Error importing <NzbFile: filename=66ef2139013741408bd97ea5ac6dc6d7.part10.rar, type=None>
2017-10-12 13:23:40,578::DEBUG::[__init__:877] Saving data for SABnzbd_nzo_Ccxocy in /home/@downloads/The.Tick.2016.S01E03.Secret.Identity.720p.AMZN.WEBRip.DDP5.1.x264-NTb.1/__ADMIN__

2017-10-12 13:24:12,412::INFO::[__init__:1058] Restarting because of crashed downloader
@Safihre

This comment has been minimized.

Copy link
Member

Safihre commented Oct 12, 2017

@mgaulton can you switch to develop, master is indeed behind and does not include the nessecary logging to fix this.
Having 2 issues is not helping, so closing this one in favor of #952.
For future reference I cannot fix this without knowing where it comes from, so I need more than just the "failed to import" lines (as described in #952):

I have added extra logging that will log any file or directory removal occurring and the NZF-ID.
In case this happens again (or to anyone having the same problem), can you search in all logs in your logs directory for the lines that contain the NZF-ID? (SABnbzd_nzf_xxxxxxx)?
If it is not logged as being deleted somewhere else, then it means that some external program is deleting the files, just like in #1047.

@Safihre Safihre closed this Oct 12, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment