Stops responding after detecting a fake

SlashQuit commented 8 years ago

After detecting a fake during the download;

Web UI stops updating.
Console stops updating or responding (started with "nzbget -s -P", then used webui to add nzb and unpause)
Fresh reload/visit to Webs UI stalls on "Loading... Please wait."

This seems to occur immediately during/after the print('[NZB] MARK=BAD') inside FakeDetector.py during main().

In FakeDetector.py (Modified by adding some "print" lines.); inside main()...

        print('[INFO] DEBUG 004 - marking as bad...')
        print('[NZB] MARK=BAD')
        print('[INFO] DEBUG 005 - marked as bad.')

Last few lines of nzbget.log;

Wed Aug 10 16:36:14 2016    INFO    Successfully downloaded Test45/some.download.set.part01.rar
Wed Aug 10 16:36:14 2016    DETAIL  Executing queue-script FakeDetector.py for Test45
Wed Aug 10 16:36:14 2016    DETAIL  FakeDetector: Detecting fake for Test45
Wed Aug 10 16:36:14 2016    INFO    FakeDetector: Found executable some.download.set/Codec/Setup.exe
Wed Aug 10 16:36:14 2016    WARNING FakeDetector: Download has media files and executables
Wed Aug 10 16:36:14 2016    INFO    FakeDetector: DEBUG 003 - in detect_fake
Wed Aug 10 16:36:14 2016    INFO    FakeDetector: DEBUG 004 - detect_fake returned true
Wed Aug 10 16:36:14 2016    INFO    FakeDetector: DEBUG 004 - marking as bad...
Wed Aug 10 16:36:14 2016    DETAIL  Successfully downloaded Test45/some.download.set.part02.rar [1/41]
Wed Aug 10 16:36:14 2016    DETAIL  Successfully downloaded Test45/some.download.set.part02.rar [2/41]

The log in the console when started with "nzbget -s" displays even less. It will respond to a ctrl+c (but never actually exits) and will terminate with a second ctrl+c.

With an unmodified script, it detects the fake but then stops updating. It does not print out this line; '[DETAIL] Detecting completed for %s' % NzbName

Upon restarting the server, it continues to download the set and marks it as a success. If I then force post-processing (from the history tab), it will mark it as bad and continue to work as normal.

FAKEDETECTOR
  PP-Script version: 1.7.

$ nzbget --serverversion
Request sent
server returned: 17.0

$ python --version
Python 2.7.11

$ grep DeleteCleanupDisk .nzbget
(No results)

$ grep DupeCheck .nzbget
DupeCheck=yes

I can reproduce this. If there is any additional info or testing required, please let me know.

hugbug commented 8 years ago

Thank you for the report.

It looks more like a bug in nzbget. I'll try to reproduce it. Does it happen every time (for bad nzbs) or only for certain nzbs?

SlashQuit commented 8 years ago

It has happened so far with every bad nzb, although for the first couple I did not realize it was related. I tried it with 17.1-testing-r1754 yesterday - same thing.

hugbug commented 8 years ago

That was a major issue :bomb::boom:

Fixed in nzbget, please try the current development version and write back.

Thanks again for the excellent bug report.

SlashQuit commented 8 years ago

17.1-testing-r1755 Try 1 - Failed to detect the executable. Server continued to respond (did not stall).

Fri Aug 12 14:24:37 2016    INFO    Successfully downloaded Test48/some.file.set.part01.rar
Fri Aug 12 14:24:37 2016    DETAIL  Executing queue-script FakeDetector.py for Test48
Fri Aug 12 14:24:37 2016    DETAIL  FakeDetector: Detecting fake for Test48
Fri Aug 12 14:24:37 2016    DETAIL  FakeDetector: Detecting completed for Test48
Fri Aug 12 14:24:37 2016    DETAIL  Executing queue-script PasswordDetector.py for Test48

... it went on to download the rest of the set.

I tried again, and success. Executable was detected, download was stopped, marked as bad, moved to history queue. I tried a 3rd and 4th time - also success. Here is what the nzbget.log shows for a successful detection;

Fri Aug 12 14:37:51 2016    INFO    Successfully downloaded Test49/some.file.set.part01.rar
Fri Aug 12 14:37:51 2016    DETAIL  Executing queue-script FakeDetector.py for Test49
Fri Aug 12 14:37:51 2016    DETAIL  FakeDetector: Detecting fake for Test49
Fri Aug 12 14:37:51 2016    INFO    FakeDetector: Found executable some.file.set/Codec/Setup.exe
Fri Aug 12 14:37:51 2016    WARNING FakeDetector: Download has media files and executables
Fri Aug 12 14:37:51 2016    INFO    FakeDetector: DEBUG 004 - marking as bad...
Fri Aug 12 14:37:51 2016    WARNING Marking Test49 as bad
Fri Aug 12 14:37:51 2016    INFO    FakeDetector: DEBUG 005 - marked as bad.
Fri Aug 12 14:37:51 2016    DETAIL  FakeDetector: Detecting completed for Test49
Fri Aug 12 14:37:52 2016    WARNING Cancelling download and deleting Test49
Fri Aug 12 14:37:52 2016    DETAIL  Deleting file some.file.set.part02.rar from download queue

The failure on the first test has me confused. I've confirmed that I used the same nzb, the data was deleted from history between tests. I did not modify the FakeDetector.py in-between tests, and the only lines I had modified in it were the 'print' lines I mentioned.

hugbug commented 8 years ago

For a clean test you should also delete directory FakeDetector in TempDir, which contains info about previously tested files.

SlashQuit commented 8 years ago

Thank you, that was it!

During "Try 1", the file "tmp/FakeDetector/32" still existed from an earlier test. There was no "creating temp file" line.

During Tries 2/3/4, a new temp file was created.

# Test before try 1
Fri Aug 12 14:07:55 2016        DETAIL  FakeDetector: Detecting fake for Test47
Fri Aug 12 14:07:55 2016        DETAIL  FakeDetector: Created temp file /home/mypath/nzbget/tmp/FakeDetector/32

# Try 1
Fri Aug 12 14:23:15 2016        DETAIL  FakeDetector: Detecting fake for Test48
Fri Aug 12 14:23:15 2016        DETAIL  FakeDetector: Detecting completed for Test48

# Try 2
Fri Aug 12 14:34:10 2016        DETAIL  FakeDetector: Detecting fake for Test49
Fri Aug 12 14:34:10 2016        DETAIL  FakeDetector: Created temp file /home/mypath/nzbget/tmp/FakeDetector/33
Fri Aug 12 14:34:10 2016        DETAIL  FakeDetector: Detecting completed for Test49

# Try 3
Fri Aug 12 14:41:39 2016        DETAIL  FakeDetector: Detecting fake for Test50
Fri Aug 12 14:41:39 2016        DETAIL  FakeDetector: Created temp file /home/mypath/nzbget/tmp/FakeDetector/34
Fri Aug 12 14:41:39 2016        DETAIL  FakeDetector: Detecting completed for Test50

# Try 4
Fri Aug 12 14:44:31 2016        DETAIL  FakeDetector: Detecting fake for Test51
Fri Aug 12 14:44:31 2016        DETAIL  FakeDetector: Created temp file /home/mypath/nzbget/tmp/FakeDetector/35
Fri Aug 12 14:44:31 2016        DETAIL  FakeDetector: Detecting completed for Test51

nzbget / FakeDetector

Stops responding after detecting a fake #6