[0.5.0b1] Pause Timer goes negative

[rAf]

When does this happen ?
Can you reproduce this ?

[MageMinds]

I also had that problem using Alpha, but I had an other problem and I though that caused the problem of negative timer.

I'm on Win 7 x64, but I don't remember what I did, I think I was trying the scheduler. I wanted to pause my download in the evening, because these days my ISP is having speed problem in my area ...

MageMinds

[shypike]

Scheduled pauses aren't counted down on the display.
So that may be the explanation: that the countdown should only be shown when
a manual temporary pause is active. Not for a normal manual pause or a scheduled one.

[onebinary]

I am having this issue as well with 0.5.0b5, and it looks like I can consistently reproduce this (even after restarting sabnzbd, haven't tried rebooting box yet).  I'm on Ubuntu x64.  Of note: ": and please mention that i haven't been able to reproduce it in windows 0.5b5"

In a couple of tests with debug enabled I set the pause time to 2 minutes.  Here are the goods (looks like the scheduler is crashing when it tries to resume after the Pause period has expired?):

Code: Select all

2009-12-25 17:11:04,013::DEBUG::[scheduler:320] Schedule resume at 1261789984.01
2009-12-25 17:11:04,013::INFO::[downloader:320] Pausing
2009-12-25 17:11:04,017::INFO::[nzbqueue:92] Saving queue
2009-12-25 17:11:04,038::INFO::[postproc:133] Saving postproc queue
2009-12-25 17:13:34,922::INFO::[__init__:754] Restarting crashed scheduler
2009-12-25 17:13:34,922::DEBUG::[scheduler:118] Scheduling RSS interval task every 15 min (delay=8)
2009-12-25 17:13:34,923::DEBUG::[scheduler:129] Scheduling VersionCheck on day 2 at 22:16
2009-12-25 17:16:20,064::INFO::[__init__:754] Restarting crashed scheduler
2009-12-25 17:16:20,064::DEBUG::[scheduler:118] Scheduling RSS interval task every 15 min (delay=5)
2009-12-25 17:16:20,064::DEBUG::[scheduler:129] Scheduling VersionCheck on day 5 at 3:57
2009-12-25 17:16:20,897::DEBUG::[scheduler:308] Resume after pause-interval
2009-12-25 17:16:20,898::INFO::[downloader:316] Resuming
2009-12-25 17:16:20,898::DEBUG::[__init__:401] PAUSED_ALL inactive
2009-12-25 17:18:13,410::DEBUG::[scheduler:320] Schedule resume at 1261790413.41
2009-12-25 17:18:13,411::INFO::[downloader:320] Pausing
2009-12-25 17:18:13,508::INFO::[nzbqueue:92] Saving queue
2009-12-25 17:18:13,532::INFO::[postproc:133] Saving postproc queue

[onebinary]

I definitely think that the scheduler is blowing up and therefore doesn't resume the queue.  I did another test as follows.

At 17:45:31 I set the queue to pause for 1 minute.  Everything looks fine, queue pauses and server connection threads terminated.  The queue should have resumed at 17:46:31 (one minute later).  But you can see nothing happens until 17:48:56 when I manually resumed the queue (just to insert some lines into the log to demonstrate that nothing was being logged at the time it should have resumed).

Then we see a few minutes later the scheduler restart message (I assume the watchdog for that runs at some interval).

Code: Select all

2009-12-25 17:45:31,915::DEBUG::[scheduler:320] Schedule resume at 1261791991.92
2009-12-25 17:45:31,915::INFO::[downloader:320] Pausing
2009-12-25 17:45:31,964::INFO::[nzbqueue:92] Saving queue
2009-12-25 17:45:31,989::INFO::[__init__:638] Saving data for queue9.sab in /data/sabnzbd/cache/queue9.sab
2009-12-25 17:45:31,990::INFO::[__init__:638] Saving data for bytes9.sab in /data/sabnzbd/cache/bytes9.sab
2009-12-25 17:45:31,990::INFO::[__init__:638] Saving data for rss_data.sab in /data/sabnzbd/cache/rss_data.sab
2009-12-25 17:45:31,991::INFO::[__init__:638] Saving data for bookmarks.sab in /data/sabnzbd/cache/bookmarks.sab
2009-12-25 17:45:31,991::INFO::[__init__:638] Saving data for watched_data.sab in /data/sabnzbd/cache/watched_data.sab
2009-12-25 17:45:31,991::INFO::[postproc:133] Saving postproc queue
2009-12-25 17:45:31,991::INFO::[__init__:638] Saving data for postproc1.sab in /data/sabnzbd/cache/postproc1.sab
2009-12-25 17:45:32,146::INFO::[downloader:677] Thread [email protected]:443: forcing disconnect
2009-12-25 17:45:33,352::INFO::[downloader:677] Thread [email protected]:443: forcing disconnect
<A bunch of the same disconnect messages, one for each of my connections (about 10 lines removed)>
2009-12-25 17:45:33,453::INFO::[downloader:677] Thread [email protected]:443: forcing disconnect
2009-12-25 17:45:33,553::INFO::[downloader:677] Thread [email protected]:443: forcing disconnect
2009-12-25 17:48:56,752::DEBUG::[rss:245] Running feedparser on <Article Indexing Site URL>
2009-12-25 17:48:58,114::DEBUG::[rss:247] Done parsing <Article Indexing Site URL>
2009-12-25 17:48:58,114::DEBUG::[rss:290] Trying title <Title Removed>
2009-12-25 17:48:58,114::DEBUG::[rss:299] Filter matched on rule 0
<A bunch of the same RSS feed reads, one for each file found (about 20 lines removed)>
2009-12-25 17:48:58,116::DEBUG::[rss:290] Trying title <Title Removed>
2009-12-25 17:48:58,116::DEBUG::[rss:299] Filter matched on rule 0
2009-12-25 17:49:08,941::INFO::[downloader:316] Resuming
2009-12-25 17:49:08,941::DEBUG::[__init__:401] PAUSED_ALL inactive
2009-12-25 17:49:08,941::INFO::[downloader:316] Resuming
2009-12-25 17:49:08,941::DEBUG::[__init__:401] PAUSED_ALL inactive
2009-12-25 17:49:08,942::INFO::[downloader:438] [email protected]:443: Initiating connection
2009-12-25 17:49:09,315::INFO::[downloader:438] [email protected]:443: Initiating connection
<A bunch of non-relevant normal stuff>
2009-12-25 17:51:00,845::INFO::[__init__:754] Restarting crashed scheduler
2009-12-25 17:51:00,845::DEBUG::[scheduler:118] Scheduling RSS interval task every 15 min (delay=9)
2009-12-25 17:51:00,846::DEBUG::[scheduler:129] Scheduling VersionCheck on day 1 at 16:37

[shypike]

It if of course possible that the scheduler crashes.
But with only this info we're never going to find out why or where.
When the scheduler is restarted, the scheduled events
are evaluated to see what the current situation should be.

[onebinary]

Well... initially I was thinking this was a regression, so I dropped back into 0.5.0b1 and 0.5.0b4 and the issue seems to persist there, and I know for sure I've used the manual pause feature with b1 and b4 (I use it all the time), so there definitely isn't a regression here.

It just occurred to me, there is something else that changed recently, I added 5 RSS feeds (and up until yesterday I had never used the RSS feed feature in SABnzbd).  Maybe this is what is causing scheduler to crash?  Maybe there is some odd data in my feeds, or my URLs are too long or something?  Any limitations with the RSS feeds feature that I should be aware of?

[shypike]

The RSS module is quite robust, it doesn't crash easily.
Please send the RSS URL you are using, to bugs at sabnzbd.org.

[feerlessleadr]

I am also having this problem using Beta 6

Currently when I manually pause for any amount of time, the time will just go negative.

Is there anything that I can upload to help sort this out?

[shypike]

Is there anything that I can upload to help sort this out?

Yes, set logging to "debug" level and zip and email the sabnzbd.ini file
after you see the negative timer again.

BTW: an important thing what nobody mentions: does SABnzbd resume when the timer goes negative
or does it stay paused?

[onebinary]

It stays paused indefinitely.  I'm going to give RC2 a try, and if I still have the issue I'll send up my RSS URLs (sorry I lagged).

[onebinary]

Same issue in RC2, RSS URLs sent to bugs email.

[shypike]

RC2 may still show negative numbers,
but it should unpause within 30 seconds.

[onebinary]

Just tested this in RC6 and it seems to be fixed?  Maybe it was something on my side?  (Although a few people reported this...)

[shypike]

We did fix one potential crash in the scheduler,
or rather a task executed by the scheduler.