Sabnzbd+ randomly quitting on OSX

[shypike]

It makes no sense to me either, except that it may mean that
the Python interpreter's runtime is crashing.
Whether that's a bug in Apple Python itself or that SABnzbd abuses it to
the extent that the runtime must crash, I cannot tell.
You have eliminated yEnc and ssl-support, the usual suspects.
All I can think of (except of just bugs in the runtime) are memory allocation issues.
Does a running SABnzbd show a steadily increasing memory usage while it's still running?

[trooper]

Does a running SABnzbd show a steadily increasing memory usage while it's still running?

Not that I nave noticed particularly.
I've noted down the memory usage as it now, and ill check it a few times today to see and report back

[trooper]

Results as follows

Code: Select all

 
Time      Real mem      Virtual mem   Private mem   Shared mem
12:00   147.3      132.0      35.9         198.0
13:48   149.8      135.1      36.2         199.8
17:02   168.3      151.6      36.2         216.5
18:10   169.5      151.8      36.2         216.9
22:23   172.1      158.5      34.5         222.0
09:38   64.9         57.1         13.7         128.2


According to the logs it crashed at some point in the night, last lines in the log before my script restarted it at 05:00 were

Code: Select all

2012-03-11 01:50:23,487::INFO::[downloader:610] Thread 1@usnews.usenetnow.net:563: server closed connection
2012-03-11 01:50:23,692::INFO::[downloader:610] Thread 15@usnews.usenetnow.net:563: server closed connection
2012-03-11 01:50:23,898::INFO::[downloader:610] Thread 12@usnews.usenetnow.net:563: server closed connection


OSX console log showed the following as usual

Code: Select all

11/03/2012 02:20:59.000 kernel: PSYNCH: pid[2590]: cvwait: thread entry with same sequence already present


[shypike]

Memory usage seems normal.
It looks like the crash occurs after downloading activity has stopped.
Can you confirm this?
Do you use SABnzbd's scheduler?
If so, is anything scheduled around the time of the crash?

[trooper]

Yup, nothing was happening at the time of the crash, as far as I can tell, full extent of the logs around that time:

Code: Select all

2012-03-11 01:10:01,320::INFO::[postproc:83] Saving postproc queue
2012-03-11 01:10:01,320::INFO::[__init__:846] Saving data for postproc1.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/postproc1.sab
2012-03-11 01:10:01,320::INFO::[downloader:229] Post-processing finished, resuming download
2012-03-11 01:10:04,342::INFO::[nzbqueue:170] Saving queue
2012-03-11 01:10:04,400::INFO::[__init__:846] Saving data for queue9.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/queue9.sab
2012-03-11 01:10:04,400::INFO::[__init__:846] Saving data for totals9.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/totals9.sab
2012-03-11 01:10:04,401::INFO::[__init__:846] Saving data for rss_data.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/rss_data.sab
2012-03-11 01:10:04,405::INFO::[__init__:846] Saving data for bookmarks.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/bookmarks.sab
2012-03-11 01:10:04,406::INFO::[__init__:846] Saving data for watched_data.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/watched_data.sab
2012-03-11 01:10:04,407::INFO::[postproc:83] Saving postproc queue
2012-03-11 01:10:04,407::INFO::[__init__:846] Saving data for postproc1.sab in /Users/trooper/Library/Application Support/SABnzbd/admin/postproc1.sab
2012-03-11 01:10:04,407::INFO::[postproc:619] Queue has finished, launching: None (None)
2012-03-11 01:50:23,487::INFO::[downloader:610] Thread 1@usnews.usenetnow.net:563: server closed connection
2012-03-11 01:50:23,692::INFO::[downloader:610] Thread 15@usnews.usenetnow.net:563: server closed connection
2012-03-11 01:50:23,898::INFO::[downloader:610] Thread 12@usnews.usenetnow.net:563: server closed connection
2012-03-11 05:45:06,022::INFO::[SABnzbd:1200] Console logging for OSX App disabled
2012-03-11 05:45:06,023::INFO::[SABnzbd:1207] --------------------------------
2012-03-11 05:45:06,023::INFO::[SABnzbd:1208] SABnzbd.py-0.6.15 (rev=d06f957a0f05a8766822acaa6de1f6d1e9f279e0)
2012-03-11 05:45:06,023::INFO::[SABnzbd:1220] Platform = posix
2012-03-11 05:45:06,023::INFO::[SABnzbd:1221] Python-version = 2.7.1 (r271:86832, Jun 16 2011, 16:59:05)
[GCC 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2335.15.00)]
2012-03-11 05:45:06,023::INFO::[SABnzbd:1222] Arguments = "/Applications/SABnzbd.app/Contents/Resources/SABnzbd.py", "-psn_0_14130553"


I do use the scheduler, but only for setting speedlimits and nothing at that time.
This is the full extent of my scheduler:

Code: Select all

 Task 1: 18:00 - Daily - speedlimit 250
 Task 2: 0:00 - Daily - speedlimit 600
 Task 3: 8:00 - Daily - speedlimit 500
 Task 4: 9:00 - Saturday - speedlimit 250
 Task 5: 9:00 - Sunday - speedlimit 250


[shypike]

That's as far as my suggestions go.
If you have more information, I am still interested.
I am planning on reorganizing things around memory management,
so possible a future version will fare better.
That is, assuming that it actually is a memory management issue.

We'll start the 0.7.0 Alpha/Beta period soon, so you might want to try those versions.
Although, so far it contains very few memory usage changes.

[trooper]

If anything turns up, then I'll let you know.
It has to be to do with the cvwait log message, which seems to be some sort of low level threading issue. But without any more logging than that, it'll be impossible to track down. Is there a higher level of logging I can switch on and give you the contents of that?
However, looking at the logs it is weird that it only closed connections to the usenet server? Every other time in the log when a connection is closed, there is an entry immediately after to re-open the connection, like this:

Code: Select all

2012-03-10 21:08:38,265::INFO::[downloader:610] Thread 5@usnews.usenetnow.net:563: server closed connection
2012-03-10 21:08:43,863::INFO::[downloader:351] 5@usnews.usenetnow.net:563: Initiating connection
2012-03-10 21:08:56,033::INFO::[downloader:539] Connecting 5@usnews.usenetnow.net:563 finished
2012-03-10 21:09:44,080::INFO::[downloader:610] Thread 9@usnews.usenetnow.net:563: server closed connection
2012-03-10 21:09:49,178::INFO::[downloader:351] 9@usnews.usenetnow.net:563: Initiating connection
2012-03-10 21:10:01,715::INFO::[downloader:539] Connecting 9@usnews.usenetnow.net:563 finished


Let me try turning off the US usenet server, and only use the european one for now (I have two usenet servers configured and enabled, a US one and an EU one)
If that has no effect, then i'll switch on the disconnect on empty queue and see what happens then

I'd be very happy to run any alpha or the like if you want me to

[shypike]

SABnzbd can only log its own actions on the source code level.
It looks like things go wrong at a lower level than that.
The default is that SABnzbd closes all server connections once the queue is empty
or when a pause occurs.
There is an option that disables the automatic disconnect
and in that case the server will timeout and close the connection itself.
What I have not been able to deduce, is whether the crash occurs during downloading,
during post processing or during idle (or just random).

[MaFL]

Hi!

I have exactly the same problems.
Sabnzbd crashes during idle for me. Randomly without any logic.

My logfiles look similar.

Code: Select all

cvwait: thread entry with same sequence already present

10.7.3 / 0.6.15

If I can help somehow.....


Regards
Matt

[shypike]

Largely the same questions.
Is the web UI active at the moment of crash (i.e. is it open in a browser window)?
Do you have third-party tools that interface with SABnzbd?

The "cvwait:..." error message is indeed produced by the Apple-written threading library for Python.
That isn't very helpful, obviously.
It does indicate that it might be a bug in the Python libraries.
But without a way of reproducing this myself, I see no possibility for repair.
Even filing a bug report with Apple seems a very long stretch.

[shypike]

Some of the things you might to is eliminate some tasks as much possible.

• Clear watched folder in Config->Folders and set scan time to 0
• Disable all RSS feeds
• Don't use the scheduler
• Disable the OSX top menu entry (a bit complicated, see here: http://wiki.sabnzbd.org/configure-special bottom of the page)

When things are "stable" re-enable one by one until it crashes again.
I realize that this will be very time-consuming.
Like I said, I haven't been able to reproduce it at all.
Will continue trying, but I might never be able to reproduce your specific configuration enough.

BTW: you say it crashes fully at random. Is there some minimum that it will keep running?

[shypike]

I want to suggest another test.
Can you install the Leopard version of SABnzbd?
You will not get the entry in the top menu bar, but other than that, things should just work.
(Except maybe Growl support).
The Leopard version is based on ActiveState's Python instead of Apple's.

If this fixes the issue, it's worth investigating the option of using ActiveState again for 0.7.0

[trooper]

Leopard version installed, i'll turn off my restart script too and report back

[trooper]

Still up and running after 30 hours, looking promising
I do miss the top menu though

[shypike]

Good news, that it works for you.
Bad news is that I will probably spend a lot of time keeping ActiveState Python and Apple Python out each others hair