sabnzbd does not download anymore (downloading state)

[jcfp]

Would any of you mind trying the previous version of sab? Procedure as follows:

• Shutdown any running instance of sab.
• Restore your samba setup if you disable or changed it.
• Get 0.6.14 source release here, and extract anywhere you want.
• Change to the dir with the extracted source release, and run with python SABnzbd.py --logging 2 under the same user account you normally use for sab.
• Download something small.

This issue with shares all of a sudden just seems a bit too much of a coincidence, especially since there's quite a few (long term) ppa users running lucid.

[hunterpr0]

With Samba:

Code: Select all

2012-02-14 14:50:31,794::INFO::[__init__:560] Adding Fleet Foxes -- Helplessness Blues (2011).nzb
2012-02-14 14:50:31,802::INFO::[misc:722] Creating directories: /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)
2012-02-14 14:50:31,830::DEBUG::[__init__:769] Saving data for SABnzbd_nzf_M1RFFA in /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__
2012-02-14 14:50:31,833::ERROR::[__init__:786] Saving /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_M1RFFA failed
2012-02-14 14:50:31,834::INFO::[__init__:787] Traceback:
Traceback (most recent call last):
  File "/root/oldsab/SABnzbd-0.6.14/sabnzbd/__init__.py", line 773, in save_data
    _f = open(path, 'wb')
IOError: [Errno 2] No such file or directory: '/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_M1RFFA'
2012-02-14 14:50:31,837::INFO::[nzbstuff:198] Saving /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_M1RFFA failed
2012-02-14 14:50:31,846::WARNING::[nzbstuff:671] Cannot save NZB admin files for "Fleet Foxes -- Helplessness Blues (2011)"

Without Samba:

Code: Select all

2012-02-14 14:52:19,647::INFO::[__init__:560] Adding Fleet Foxes -- Helplessness Blues (2011).nzb
2012-02-14 14:52:19,650::INFO::[misc:722] Creating directories: /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)
2012-02-14 14:52:19,656::DEBUG::[__init__:769] Saving data for SABnzbd_nzf_6Pj6oX in /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__
2012-02-14 14:52:19,658::INFO::[nzbstuff:423] File 02 Bedouin Dress.mp3 added to queue
2012-02-14 14:52:19,662::DEBUG::[__init__:769] Saving data for SABnzbd_nzf_O8v90q in /mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__(...etc...)

Without samba, it just downloads it like mad.

[jcfp]

So the recent update isn't the cause. Samba it is, then. What's the underlying OS, filesystem, etc, of the samba share? Is it part of a raid array?

[hunterpr0]

nope. It's an ext4 formatted, single disk, single partition USB disk, shared by OpenWRT (linux) as samba. In the house are win7 clients, mac clients and linux clients that are all happy to read and write to it without a hitch.

[hunterpr0]

I'll try baking a small PoC to see if python never wants to write to this disk. That would be weird, since even Sickbeard is happy to oblige with it.

update:

Code: Select all

root@tobion:/mnt/sharedoos/news/incomplete# python
Python 2.6.5 (r265:79063, Apr 16 2010, 13:09:56)
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> f = open('myfile', 'w')
>>> print f
<open file 'myfile', mode 'w' at 0xb786a0d0>
>>> f.write('this is a test\n')
>>> f.close;
<built-in method close of file object at 0xb786a0d0>
>>> exit()
root@tobion:/mnt/sharedoos/news/incomplete# ls
myfile
root@tobion:/mnt/sharedoos/news/incomplete# cat myfile
this is a test
root@tobion:/mnt/sharedoos/news/incomplete#

works just fine.

[hunterpr0]

Ok, did a full strace and found some interesting stuff.

Full strace is on http://sinas.rename-it.nl/~tobias/output2 (watch out, 1.1mb plaintext). Ctrl+f for 'fleet foxes' since this is the file i added and where the magic stuff happens. I'll paste some excerpts.

Code: Select all

Worker 4653 receives something about some 'fleet foxes'. Work to do!

4653  recv(8, "</file>\n<file subject=\"Fleet Fox"..., 8192, 0) = 8192


4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)", 0xb553c95c) = -1 ENOENT (No such file or directory)
There is no directory yet.

4653  stat64("/mnt/sharedoos/news/incomplete", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)", 0xb553c46c) = -1 ENOENT (No such file or directory)
4653  mkdir("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)", 0777) = 0
4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", 0xb553ccdc) = -1 ENOENT (No such file or directory)
4653  mkdir("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", 0777 <unfinished ...>
4653  <... mkdir resumed> )             = 0

So now we have the dirstructure in place.

4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", {st_mode=S_IFDIR|0700, st_size=0, ...}) = 0
check the ADMIN dir...

4653  open("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_JkQmJX", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE|O_NOFOLLOW, 0600) = 12
and create an admin file. It is created as filehandle 12.

4653  fcntl64(12, F_GETFD)              = 0
4653  fcntl64(12, F_SETFD, FD_CLOEXEC)  = 0
4653  close(12)                         = 0
Do stuff, close it. Done!

but then...

4653  open("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_JkQmJX", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = -1 ENOENT (No such file or directory)
?! where did the file go? Why is it reading it as 0666 now?

The worker becomes confused enough to kill itself, so it reinits.

4653  open("/root/oldsab/SABnzbd-0.6.14/sabnzbd/__init__.py", O_RDONLY|O_LARGEFILE) = 12


It checks if the directory is still there, and gets directory contents twice. (why twice? No clue.)

4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", {st_mode=S_IFDIR|0700, st_size=0, ...}) = 0
4653  open("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 12
4653  getdents64(12, /* 3 entries */, 32768) = 88
4653  getdents64(12, /* 0 entries */, 32768) = 0
4653  close(12)                         = 0
4653  open("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 12
4653  getdents64(12,  <unfinished ...>
4653  <... getdents64 resumed> /* 3 entries */, 32768) = 88
4653  getdents64(12, /* 0 entries */, 32768) = 0
4653  close(12)                         = 0

Then something interesting happens.

4653  stat64("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_JkQmJX", {st_mode=S_IFREG|0700, st_size=0, ...}) = 0

Obviously the file still exists (stat returns 0, which is OK) and it was found by the above open(). Why did it not find it before?! Timing?

4653  unlink("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__/SABnzbd_nzf_JkQmJX") = 0

Damagecontrol; remove the adminfile and all dirs.

4653  rmdir("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)/__ADMIN__") = 0
4653  stat64("/mnt/sharedoos/news/incomplete", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
4653  rmdir("/mnt/sharedoos/news/incomplete/Fleet Foxes -- Helplessness Blues (2011)") = 0

And we're clear.

I can find in the code where the second 'write' happens that errors here (in __init__.py, near line 772, but I cannot find where the initial write happens. Can somebody point me there? Perhaps all this is just a big timing problem for Samba. Or something else.

Which dev now knows 'ah, i see whats going on here' ?

[jcfp]

Just guessing here, but maybe some kind of disk caching going on? Client or server side or even both ends.