PostProc fails on set with unicode character

[Smudge]

Version: 0.7.3
OS: Mac OS X 10.8.2
Install-type: OSX .app
Skin (if applicable): Plush Gold
Firewall Software: None
Are you using IPV6? no
Is the issue reproducible? yes

The PostProcessing function failed when attempting to process a set. I think it doesn't handle the set properly if it includes unicode characters in the set name.

Here are the relevant log entries

Code: Select all

2012-10-06 19:45:49,072::DEBUG::[rss:324] Running feedparser on https://www.newzxxx2.ch/[REMOVED]
2012-10-06 19:45:51,066::DEBUG::[rss:326] Done parsing https://www.newzxxx2.ch/[REMOVED]
2012-10-06 19:45:51,066::DEBUG::[rss:392] Trying title SubjectTest²
2012-10-06 19:45:51,066::DEBUG::[rss:419] Filter matched on rule 0
2012-10-06 19:45:51,067::INFO::[rss:579] Adding 1234567 (SubjectTest²) to queue
2012-10-06 19:45:51,068::INFO::[__init__:477] Fetching msgid 6942498 from www.newzbin2.es
2012-10-06 19:45:51,069::INFO::[nzbqueue:176] Saving queue
2012-10-06 19:45:51,069::DEBUG::[__init__:820] Saving data for SABnzbd_nzo_N9OniY in /Users/smudge/Library/Application Support/SABnzbd/admin/future
2012-10-06 19:45:51,069::INFO::[__init__:895] Saving data for queue9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/queue9.sab
2012-10-06 19:45:51,572::DEBUG::[newzbin:105] Popping msgid 1234567
2012-10-06 19:45:51,573::INFO::[newzbin:152] Fetching NZB for Newzbin report #1234567
2012-10-06 19:45:58,055::INFO::[newzbin:251] Successfully fetched report 1234567 - SubjectTest^2 (cat=Movies) (SubjectTest^2.nzb)
2012-10-06 19:45:58,056::INFO::[__init__:884] /Users/smudge/Library/Application Support/SABnzbd/admin/future/SABnzbd_nzo_N9OniY removed
2012-10-06 19:45:58,056::INFO::[nzbqueue:213] Regenerating item: SABnzbd_nzo_N9OniY
2012-10-06 19:45:58,446::INFO::[misc:792] Creating directories: /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²
2012-10-06 19:45:58,452::DEBUG::[__init__:820] Saving data for SABnzbd_nzf_Cy1g8H in /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__
2012-10-06 19:45:58,452::INFO::[nzbstuff:429] File FilenameTest²_20121006.par2 added to queue
[remaining files added to queue]
2012-10-06 19:45:58,772::INFO::[__init__:565] Backing up /Users/smudge/usenet/SABnzbd/.nzbBackups/SubjectTest^2.nzb.gz
2012-10-06 19:45:58,851::INFO::[__init__:565] Backing up /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SubjectTest^2.nzb.gz
2012-10-06 19:45:58,934::INFO::[nzbqueue:176] Saving queue
2012-10-06 19:45:58,934::DEBUG::[__init__:820] Saving data for SABnzbd_nzo_N9OniY in /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__
2012-10-06 19:45:58,937::INFO::[__init__:895] Saving data for queue9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/queue9.sab
2012-10-06 19:46:06,610::INFO::[__init__:895] Saving data for rss_data.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/rss_data.sab
2012-10-06 19:46:06,619::INFO::[rss:505] Finished scheduled RSS read-out

2012-10-09 03:34:03,551::INFO::[panic:247] Lauching browser with http://localhost:8085/sabnzbd
2012-10-09 03:34:37,881::DEBUG::[nzbqueue:431] Resumed nzo: SABnzbd_nzo_N9OniY
2012-10-09 03:35:04,845::DEBUG::[nzbstuff:207] Finishing import on FilenameTest²_20121006.par2
2012-10-09 03:35:04,889::DEBUG::[__init__:854] Loading data for SABnzbd_nzf_Cy1g8H from /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_Cy1g8H
2012-10-09 03:35:04,917::INFO::[downloader:375] [email protected]:563: Initiating connection
[files downloading]
2012-10-09 03:35:06,886::INFO::[assembler:87] Decoding /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/FilenameTest²_20121006.par2 yenc
2012-10-09 03:35:06,908::DEBUG::[assembler:108] Got md5pack for set FilenameTest²_20121006
2012-10-09 03:45:51,107::DEBUG::[nzbstuff:207] Finishing import on FilenameTest²_20121006.r46
2012-10-09 03:45:51,108::DEBUG::[__init__:854] Loading data for SABnzbd_nzf_VIJ3c8 from /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_VIJ3c8
2012-10-09 03:48:21,019::DEBUG::[__init__:820] Saving data for SABnzbd_nzo_N9OniY in /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__
2012-10-09 03:48:21,260::INFO::[__init__:895] Saving data for totals9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/totals9.sab
2012-10-09 03:48:21,261::INFO::[assembler:87] Decoding /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/FilenameTest²_20121006.r46 yenc
2012-10-09 03:48:26,486::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzo_N9OniY removed
2012-10-09 03:48:26,487::INFO::[nzbqueue:176] Saving queue
2012-10-09 03:48:26,487::INFO::[__init__:895] Saving data for queue9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/queue9.sab
2012-10-09 03:48:26,490::INFO::[postproc:84] Saving postproc queue
2012-10-09 03:48:26,490::INFO::[__init__:895] Saving data for postproc1.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/postproc1.sab
2012-10-09 03:48:26,495::INFO::[downloader:238] Waiting for post-processing to finish
2012-10-09 03:48:26,498::INFO::[postproc:280] Starting PostProcessing on SubjectTest² => Repair:True, Unpack:True, Delete:True, Script:None, Cat:*
2012-10-09 03:48:27,005::INFO::[postproc:546] Par2 check starting on SubjectTest²
2012-10-09 03:48:27,006::INFO::[postproc:561] Running repair on set FilenameTest²_20121006
2012-10-09 03:48:27,014::ERROR::[postproc:484] Post Processing Failed for SubjectTest² ()
2012-10-09 03:48:27,015::INFO::[postproc:486] Traceback: 
Traceback (most recent call last):
  File "sabnzbd/postproc.pyc", line 284, in process_job
  File "sabnzbd/postproc.pyc", line 563, in parring
  File "sabnzbd/newsunpack.pyc", line 775, in par2_repair
  File "sabnzbd/newsunpack.pyc", line 1297, in QuickCheck
KeyError: 'FilenameTest\xc3\x82\xc2\xb2_20121006.r46'
2012-10-09 03:48:27,521::INFO::[postproc:519] Cleaning up SubjectTest² (keep_basic=True)
2012-10-09 03:48:27,522::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_h8cXrI removed
2012-10-09 03:48:27,522::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_tKQVZB removed
2012-10-09 03:48:27,523::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_pxzWgb removed
2012-10-09 03:48:27,523::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_z9V_S0 removed
2012-10-09 03:48:27,524::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_1FfM5l removed
2012-10-09 03:48:27,524::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_JbT8aa removed
2012-10-09 03:48:27,525::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_S1DN14 removed
2012-10-09 03:48:27,525::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_JpX_bg removed
2012-10-09 03:48:27,525::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_iAxipP removed
2012-10-09 03:48:27,526::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_jzzLMl removed
2012-10-09 03:48:27,526::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_4k56Wa removed
2012-10-09 03:48:27,526::INFO::[__init__:884] /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__/SABnzbd_nzf_u3wmsx removed
2012-10-09 03:48:27,529::INFO::[misc:1260] Cannot remove folder /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__
2012-10-09 03:48:27,529::INFO::[misc:1260] Cannot remove folder /Users/smudge/usenet/SABnzbd/.incomplete/SubjectTest²/__ADMIN__

Here is the section of the QuickCheck function. Line 1297 is the checking of the nzf.md5sum value to the md5pack values. I think it doesn't handle the escaped unicode characters in the key name properly.

Code: Select all

        for nzf in nzf_list:
            if file == name_fixer(nzf.filename):
                found = True
                if (nzf.md5sum is not None) and nzf.md5sum == md5pack[file]:

It might be related to this but another issue I noticed is the conversion from latin-1 to unicode doesn't seem to be proper.

The NZB XML file has a title with a unicode character (superscript character ² in this case) as escaped HTML text of ²

Code: Select all

<title>TestSubject&#178;</title>

It is handled by the rss module with the "atitle" variable as a Latin1 string converting the ² to the byte B2

Code: Select all

atitle = latin1(jobs[link].get('title', ''))

This is logged as such

Code: Select all

        logging.debug('Trying title %s', atitle)
2012-10-06 19:45:51,066::DEBUG::[rss:392] Trying title TestSubject²

The "title" variable is the "atitle" converted to unicode, which becomes bytes C2 B2.

Code: Select all

title = unicoder(atitle)

This is logged as such

Code: Select all

        logging.info("Adding %s (%s) to queue", m.group(3), title)
2012-10-06 19:45:51,067::INFO::[rss:579] Adding 1234567 (TestSubject²) to queue

Note that the log file is in latin-1 encoding so the 2 characters ² are proper here. If I reload the log file with unicode-8 encoding, these lines show properly as

Code: Select all

2012-10-06 19:45:51,067::INFO::[rss:579] Adding 1234567 (TestSubject²) to queue

However, it is interpreting the unicode superscript character ² (C2 B2) as 2 separate Latin1 characters (C2 and B2). The C2 is the  char (Latin capital A with circumflex accent) and is converted to the unicode bytes C3 82. This makes the title entry become "C3 82 C2 B2".

When it goes to compare the checksum, it is looking it up using the 2 characters (C3 82 C2 B2) instead of the proper single unicode character (C2 B2).

Code: Select all

KeyError: 'FilenameTest\xc3\x82\xc2\xb2_20121006.r46'

Either it is the wrong key name or it can't handle the escaped codes.


I hope this is useful.

P.S. I noticed that the newzbin module archives the NZB changing the unicode superscript 2 character to two different characters, a circumflex accent and the number 2 (although I don't think it has anything to do with this issue). Perhaps it should be saved as unicode instead?

Code: Select all

2012-10-06 19:45:58,055::INFO::[newzbin:251] Successfully fetched report 1234567 - SubjectTest^2 (cat=XXX) (SubjectTest^2.nzb)

[shypike]

SABnzbd doesn't handle Unicode at all, it's limited to CP1252 ( or Latin-1).
Nevertheless, RSS titles should be dealt with properly and "illegal" characters removed.
I'll see what I can do for now.
Release 0.8.0 will be a full Unicode implementation.

[shypike]

I don't think your analysis is correct.
The troublesome spot is indeed in QuickCheck.
However, QuickCheck doesn't use names from the RSS feed but file names coming from the yEnc protocol.
yEnc itself is troublesome, because it has no defined character encoding.
I would need the actual NZB file that triggers the issue.
Can you email that file to [email protected] ?

[Smudge]

It is very possible that I'm not completely correct. I don't know python at all. However, I think some of it is still relevant.
Given that you said proper unicode support is coming later, this might not be much of an issue but I am seeing more and more unicode characters on usenet.

I did another test with a nzb file with different unicode characters in it, for the nzb filename, the subject (subject part), and subject (filename part).
I saw the assembler module is what picked up the set name from the filename that was in the yEnc header of the par2 file and that it wasn't part of the nzb at all.
The filename has the ² character as a single B2 byte. I checked this by downloading the raw body of the article and looked at it with a hex editor. This example shows that it is using latin1 encoding but the NNTP spec says the body can be in any encoding format.

That module is also creating the md5 set, which is being used by QuickCheck later. Since the debug log for assembler doesn't show the characters in escaped hex, I can't tell what is going on but I'm guessing that all the log entries are showing 2 bytes for every file and set name that something early on is calling the unicoder function thus translating to unicode. Then within QuickCheck, it is taking the 2 bytes and translating yet again, thus ending up with the 4 bytes as I detailed above.

Here is the log output, using latin1 encoding.

Code: Select all

2012-10-17 17:23:45,265::INFO::[assembler:87] Decoding /Users/smudge/usenet/SABnzbd/.incomplete/Test2-NZBFileName±/Testfile².par2 yenc
2012-10-17 17:23:45,284::DEBUG::[assembler:112] Got md5pack for set Testfile²

2012-10-17 17:23:48,669::INFO::[postproc:474] Traceback: 
Traceback (most recent call last):
  File "sabnzbd/postproc.pyc", line 272, in process_job
  File "sabnzbd/postproc.pyc", line 551, in parring
  File "sabnzbd/newsunpack.pyc", line 785, in par2_repair
  File "sabnzbd/newsunpack.pyc", line 1317, in QuickCheck
KeyError: 'Testfile\xc3\x82\xc2\xb2.r46'

I will email you the nzb that first showed this issue.

During my testing this evening, I created a test post (a png image and par2 files) and uploaded it to alt.binaries.test. When I tried to download the files using the nzb, SABnzbd actually hung on it. The log didn't show any errors but it just stopped processing anything. After a couple of minutes, I deleted the entry from the download queue screen. Perhaps something else is getting in a loop regarding the unicode characters. Of course I'll send you this test NZB too.

Code: Select all

2012-10-17 18:33:51,699::INFO::[dirscanner:313] Trying to import /Users/smudge/usenet/SABnzbd/image³_parfiles®.nzb
2012-10-17 18:33:52,734::INFO::[misc:781] Creating directories: /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®
2012-10-17 18:33:52,735::DEBUG::[__init__:821] Saving data for SABnzbd_nzf_1IEeHv in /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__
2012-10-17 18:33:52,736::INFO::[nzbstuff:426] File unicodetest [1/3] - "image³.png" yEnc (1/1) added to queue
2012-10-17 18:33:52,736::DEBUG::[__init__:821] Saving data for SABnzbd_nzf_gML_hn in /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__
2012-10-17 18:33:52,736::INFO::[nzbstuff:426] File unicodetest [2/3] - "parfiles®.par2" yEnc (1/1) added to queue
2012-10-17 18:33:52,737::DEBUG::[__init__:821] Saving data for SABnzbd_nzf_pgnzjN in /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__
2012-10-17 18:33:52,737::INFO::[nzbstuff:426] File unicodetest [3/3] - "parfiles®.vol0+1.PAR2" yEnc (1/2) added to queue
2012-10-17 18:33:52,737::INFO::[__init__:561] Backing up /Users/smudge/usenet/SABnzbd/.nzbBackups/image³_parfiles®.nzb.gz
2012-10-17 18:33:52,738::INFO::[__init__:561] Backing up /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__/image³_parfiles®.nzb.gz
2012-10-17 18:33:52,739::INFO::[nzbqueue:204] Saving queue
2012-10-17 18:33:52,739::DEBUG::[__init__:821] Saving data for SABnzbd_nzo_8nXK0m in /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__
2012-10-17 18:33:52,740::INFO::[__init__:896] Saving data for queue9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/queue9.sab
2012-10-17 18:35:09,190::INFO::[downloader:208] Resuming
2012-10-17 18:35:09,191::DEBUG::[__init__:524] PAUSED_ALL inactive
2012-10-17 18:35:09,191::INFO::[downloader:208] Resuming
2012-10-17 18:35:09,191::DEBUG::[__init__:524] PAUSED_ALL inactive
2012-10-17 18:35:10,192::DEBUG::[nzbstuff:208] Finishing import on unicodetest [2/3] - "parfiles®.par2" yEnc (1/1)
2012-10-17 18:35:10,193::DEBUG::[__init__:855] Loading data for SABnzbd_nzf_gML_hn from /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__/SABnzbd_nzf_gML_hn
2012-10-17 18:35:10,193::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-10-17 18:35:10,194::DEBUG::[nzbstuff:208] Finishing import on unicodetest [1/3] - "image³.png" yEnc (1/1)
2012-10-17 18:35:10,194::DEBUG::[__init__:855] Loading data for SABnzbd_nzf_1IEeHv from /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__/SABnzbd_nzf_1IEeHv
2012-10-17 18:35:10,194::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-10-17 18:35:10,194::DEBUG::[nzbstuff:208] Finishing import on unicodetest [3/3] - "parfiles®.vol0+1.PAR2" yEnc (1/2)
2012-10-17 18:35:10,195::DEBUG::[__init__:855] Loading data for SABnzbd_nzf_pgnzjN from /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__/SABnzbd_nzf_pgnzjN
2012-10-17 18:35:10,195::INFO::[downloader:375] [email protected]:563: Initiating connection
2012-10-17 18:35:11,380::INFO::[downloader:566] Connecting [email protected]:563 finished
2012-10-17 18:35:11,381::INFO::[downloader:566] Connecting [email protected]:563 finished
2012-10-17 18:35:11,381::INFO::[downloader:566] Connecting [email protected]:563 finished
2012-10-17 18:35:12,404::DEBUG::[decoder:97] Decoding <Article: [email protected], bytes=1950, partnum=1, art_id=None>
2012-10-17 18:35:12,405::DEBUG::[__init__:821] Saving data for SABnzbd_nzo_8nXK0m in /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/__ADMIN__
2012-10-17 18:35:12,406::INFO::[__init__:896] Saving data for totals9.sab in /Users/smudge/Library/Application Support/SABnzbd/admin/totals9.sab
2012-10-17 18:35:12,406::INFO::[assembler:87] Decoding /Users/smudge/usenet/SABnzbd/.incomplete/image³_parfiles®/image³.png yenc
2012-10-17 18:35:12,485::DEBUG::[decoder:97] Decoding <Article: [email protected], bytes=400, partnum=1, art_id=None>
2012-10-17 18:35:16,825::DEBUG::[bpsmeter:253] bps: 69868.2951266
2012-10-17 18:35:21,831::DEBUG::[bpsmeter:253] bps: 28050.8225589
2012-10-17 18:35:26,836::DEBUG::[bpsmeter:253] bps: 11263.4157359
2012-10-17 18:35:31,841::DEBUG::[bpsmeter:253] bps: 4522.57433639
2012-10-17 18:35:36,847::DEBUG::[bpsmeter:253] bps: 1815.77768232
2012-10-17 18:35:41,854::DEBUG::[bpsmeter:253] bps: 728.923160065
2012-10-17 18:35:46,859::DEBUG::[bpsmeter:253] bps: 292.662467493
2012-10-17 18:35:51,865::DEBUG::[bpsmeter:253] bps: 117.494687713
2012-10-17 18:35:56,871::DEBUG::[bpsmeter:253] bps: 47.1752520199
2012-10-17 18:36:01,876::DEBUG::[bpsmeter:253] bps: 18.9433081583
2012-10-17 18:36:06,882::DEBUG::[bpsmeter:253] bps: 7.60491615308
2012-10-17 18:36:11,887::DEBUG::[bpsmeter:253] bps: 3.05380046634
2012-10-17 18:36:16,892::DEBUG::[bpsmeter:253] bps: 1.22622581291
2012-10-17 18:36:21,899::DEBUG::[bpsmeter:253] bps: 0.492247077212
2012-10-17 18:36:26,904::DEBUG::[bpsmeter:253] bps: 0.197640015298
2012-10-17 18:36:31,910::DEBUG::[bpsmeter:253] bps: 0.0793554968997
2012-10-17 18:36:36,916::DEBUG::[bpsmeter:253] bps: 0.031858377959
2012-10-17 18:36:41,921::DEBUG::[bpsmeter:253] bps: 0.012790841105
2012-10-17 18:40:12,509::INFO::[downloader:643] Thread [email protected]:563: server closed connection
2012-10-17 18:40:12,570::INFO::[downloader:643] Thread [email protected]:563: server closed connection
2012-10-17 18:40:14,941::INFO::[downloader:643] Thread [email protected]:563: server closed connection

[shypike]

I found the troublesome spots.
Your example files laid bare two separate bugs, one in nzbstuff.py and one in newsunpack.py.
Confusion about whether names are already encoded platform-specific or not.
Will be fixed in 0.7.5.
Thanks for your very informative reports.

(High time the Unicode version gets ready, so these kinds of bugs are gone for good.)

[Smudge]

Very happy to help. and let me say a big thank you for all your hard work. I greatly appreciate your software.