Bugs and quirks in 1.0.5 (svn)

[thorwak]

Could be worth checking for packet loss (is the InterNet connection "glitchy"?) In general TCP/IP handles this even if there's packet loss but it could trigger timeouts.

Also check dmesg for general system errors if you haven't.

[Reab4]

Sometimes when I request it to make an nzb, it either hangs with an empty progress bar or generates no nzb. The empty progress bar is removed after an urdd cycle. The log file has a lot of 'queueing MAKE_NZB ##' in a row and sometimes a notice: 'Item queued too often, task cancelled: MAKE_NZB ##':

07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    NOTICE    Item queued too often, task cancelled: MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:22    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23
07 May 2010    11:15:21    DEBUG    Queueing MAKE_NZB 23

Is this due to re-shuffling of the task list or some odd behavior?

[spearhead]

That's pretty weird.

Do you run any other tasks as well? Can you describe steps to reproduce this? Is there anything between these queueing messages?

[spearhead]

Anyway I made a few changes to the code in svn. Test it out if you wish. (you are on svn right?)

[Reab4]

Yeah I work from svn and updated to 1487; Lets see if it happens again.
It's kinda hard to find a clue in the log.
 

[spearhead]

if you run it from the console, you sometimes get more info...

[Reab4]

I had this problem again.
Second paragraph show a part of the raw log. The log is rather long: 276MB. (Looks like there is no rotation) 


09 May 2010    17:35:21    DEBUG    fn:do_cancel_all() pid:21130 (9961472 10223616)
09 May 2010    13:57:36    NOTICE    Item queued too often, task cancelled: MAKE_NZB 39
09 May 2010    13:57:36    DEBUG    updating status Cancelled
09 May 2010    13:57:36    DEBUG    updating status Cancelled
09 May 2010    13:57:36    NOTICE    Item queued too often, task cancelled: MAKE_NZB 40
09 May 2010    13:57:36    NOTICE    Item queued too often, task cancelled: MAKE_NZB 38
09 May 2010    13:57:36    DEBUG    updating status Cancelled
09 May 2010    13:57:36    DEBUG    updating status Cancelled
09 May 2010    13:57:36    NOTICE    Item queued too often, task cancelled: MAKE_NZB 41
09 May 2010    13:57:36    NOTICE    Item queued too often, task cancelled: MAKE_NZB 42
09 May 2010    13:57:36    DEBUG    updating status Cancelled
08 May 2010    14:36:13    NOTICE    Item queued too often, task cancelled: MAKE_NZB 34
08 May 2010    14:36:13    DEBUG    updating status Cancelled
08 May 2010    14:36:13    DEBUG    updating status Cancelled
08 May 2010    14:36:13    NOTICE    Item queued too often, task cancelled: MAKE_NZB 35
08 May 2010    14:36:13    NOTICE    Item queued too often, task cancelled: MAKE_NZB 33
08 May 2010    14:36:13    DEBUG    updating status Cancelled
08 May 2010    14:36:13    DEBUG    updating status Cancelled
08 May 2010    14:36:13    NOTICE    Item queued too often, task cancelled: MAKE_NZB 36
08 May 2010    14:36:13    NOTICE    Item queued too often, task cancelled: MAKE_NZB 37

May 09 13:57:36 DebNAS urdd: NOTICE Item queued too often, task cancelled: MAKE_NZB 38
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG updating status Running
May 09 13:57:36 DebNAS urdd: DEBUG worker forked: PID 27323
May 09 13:57:36 DebNAS urdd: DEBUG fn:queue_delete() pid:21130 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:handle_queue_item() pid:27323 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:do_make_nzb() pid:27323 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG Dl still locked, sleeping
May 09 13:57:36 DebNAS urdd: DEBUG fn:shutdown_handler() pid:27323 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG shutdown handler called as child
May 09 13:57:36 DebNAS urdd: DEBUG Child exited (rc: 14)
May 09 13:57:36 DebNAS urdd: DEBUG Thread status 1; server: 0
May 09 13:57:36 DebNAS urdd: DEBUG Dl still locked, pausing
May 09 13:57:36 DebNAS urdd: DEBUG Queueing MAKE_NZB 39
May 09 13:57:36 DebNAS urdd: DEBUG updating status Cancelled
May 09 13:57:36 DebNAS urdd: NOTICE Item queued too often, task cancelled: MAKE_NZB 39
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG updating status Running
May 09 13:57:36 DebNAS urdd: DEBUG worker forked: PID 27324
May 09 13:57:36 DebNAS urdd: DEBUG fn:queue_delete() pid:21130 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:handle_queue_item() pid:27324 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:do_make_nzb() pid:27324 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG Dl still locked, sleeping
May 09 13:57:36 DebNAS urdd: DEBUG fn:shutdown_handler() pid:27324 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG shutdown handler called as child
May 09 13:57:36 DebNAS urdd: DEBUG Child exited (rc: 14)
May 09 13:57:36 DebNAS urdd: DEBUG Thread status 1; server: 0
May 09 13:57:36 DebNAS urdd: DEBUG Dl still locked, pausing
May 09 13:57:36 DebNAS urdd: DEBUG Queueing MAKE_NZB 40
May 09 13:57:36 DebNAS urdd: DEBUG updating status Cancelled
May 09 13:57:36 DebNAS urdd: NOTICE Item queued too often, task cancelled: MAKE_NZB 40
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 13:57:36 DebNAS urdd: DEBUG updating status Running
May 09 13:57:36 DebNAS urdd: DEBUG worker forked: PID 27325
May 09 13:57:36 DebNAS urdd: DEBUG fn:queue_delete() pid:21130 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:handle_queue_item() pid:27325 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG fn:do_make_nzb() pid:27325 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG Dl still locked, sleeping
May 09 13:57:36 DebNAS urdd: DEBUG fn:shutdown_handler() pid:27325 (10223616 10223616)
May 09 13:57:36 DebNAS urdd: DEBUG shutdown handler called as child
May 09 13:57:36 DebNAS urdd: DEBUG Child exited (rc: 14)
May 09 13:57:36 DebNAS urdd: DEBUG Thread status 1; server: 0

[Reab4]

I just noticed that the urdd was offline.
I'm on 1492. Restarting seemed no issue.
Has the DB changed? - do I need updating?

Edit:
It crashed while generating an nzb file with a message window after 2s: 'waited too long'

May 09 19:15:41 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)May 09 19:15:41 DebNAS urdd: DEBUG read line: [DISKFREE p1]May 09 19:15:41 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)May 09 19:15:45 DebNAS urdd: DEBUG Incoming connection from host localhost:36688May 09 19:15:45 DebNAS urdd: DEBUG read line: [USER Reab4]
May 09 19:15:45 DebNAS urdd: DEBUG read line: [PASS XXX]
May 09 19:15:45 DebNAS urdd: DEBUG read line: [DISKFREE h]
May 09 19:15:45 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)
May 09 19:15:45 DebNAS urdd: DEBUG read line: [DISKFREE p1]
May 09 19:15:45 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)
May 09 19:15:49 DebNAS urdd: DEBUG Incoming connection from host localhost:36689May 09 19:15:49 DebNAS urdd: DEBUG read line: [USER Reab4]
May 09 19:15:49 DebNAS urdd: DEBUG read line: [PASS XXX]
May 09 19:15:49 DebNAS urdd: DEBUG read line: [DISKFREE h]
May 09 19:15:49 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)
May 09 19:15:49 DebNAS urdd: DEBUG read line: [DISKFREE p1]
May 09 19:15:49 DebNAS urdd: DEBUG fn:do_diskfree() pid:14559 (9175040 9175040)
May 09 19:15:52 DebNAS urdd: DEBUG Incoming connection from host localhost:36690
May 09 19:15:52 DebNAS urdd: DEBUG read line: [USER Reab4]
May 09 19:15:52 DebNAS urdd: DEBUG read line: [PASS XXX]
May 09 19:15:52 DebNAS urdd: DEBUG read line: [MAKE_NZB]
May 09 19:15:52 DebNAS urdd: DEBUG fn:create_make_nzb() pid:14559 (9175040 9175040)
May 09 19:15:52 DebNAS urdd: DEBUG Connecting to mysql @ localhost
May 09 19:15:52 DebNAS urdd: CRITICAL An error occured during startup of URD daemon: Could not execute SQL query "INSERT INTO downloadinfo ("name", "unpar", "unrar", "subdl", "delete_files", "status", "destination", "username", "preview", "size", "first_run") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)" Could not execute SQL query "INSERT INTO downloadinfo ("name", "unpar", "unrar", "subdl", "delete_files", "status", "destination", "username", "preview", "size", "first_run") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)" mysql error: [1054: Unknown column 'subdl' in 'field list'] in EXECUTE("INSERT INTO downloadinfo ("name", "unpar", "unrar", "subdl", "delete_files", "status", "destination", "username", "preview", "size", "first_run") VALUES ('', 0, 0, 0, 0, 0, '', 'Reab4', 3, 0, 1)")
May 09 19:15:52 DebNAS urdd: CRITICAL
May 09 19:15:52 DebNAS urdd: NOTICE is there another URD daemon running?
May 09 19:15:52 DebNAS urdd: DEBUG #0 /usr/share/urd_svn/urdd/download_functions.php(430): DatabaseConnection->insert_query('downloadinfo', Array, Array)
May 09 19:15:52 DebNAS urdd: DEBUG #1 /usr/share/urd_svn/urdd/do_functions.php(316): add_download(Object(DatabaseConnection), 'Reab4', 0, 0, 0, 0, 0, '', 3)
May 09 19:15:52 DebNAS urdd: DEBUG #2 /usr/share/urd_svn/urdd/urdd_command.php(165): create_make_nzb(Object(DatabaseConnection), Object(server_data), 'Reab4', 49)
May 09 19:15:52 DebNAS urdd: DEBUG #3 /usr/share/urd_svn/urdd/urdd.php(452): do_command(Object(DatabaseConnection), 'MAKE_NZB', '', Object(conn_list), Resource id #23111, Object(server_data), NULL, NULL, false)
May 09 19:15:52 DebNAS urdd: DEBUG #4 /usr/share/urd_svn/urdd/urdd.php(536): read_sockets(Object(DatabaseConnection), Array, Array, Object(conn_list), Object(server_data))
May 09 19:15:52 DebNAS urdd: DEBUG #5 /usr/share/urd_svn/urdd/urdd.php(875): server(Array, Object(DatabaseConnection), Object(server_data))
May 09 19:15:52 DebNAS urdd: DEBUG #6 {main}
May 09 19:15:52 DebNAS urdd: ERROR Exception: Could not execute SQL query "SELECT "value" FROM preferences WHERE "option" = 'urdd_startup' AND "userID" = 0" mysql error: [2006: MySQL server has gone away] in EXECUTE("SELECT "value" FROM preferences WHERE "option" = 'urdd_startup' AND "userID" = 0 LIMIT 2147483647")
May 09 19:15:52 DebNAS urdd: ERROR
May 09 19:15:52 DebNAS urdd: DEBUG fn:shutdown_handler() pid:14559 (9175040 9175040)
May 09 19:15:52 DebNAS urdd: INFO shutdown handler called as parent

[spearhead]

yea the db needs updating
include install/update_db_1.0.4_to_1.0.5_mysql.sql
unless you haven't the dirty flags on all parts_ and binaries_ tables (an earlier update since 1.0.4)
then run update.sh 1.0.4

[spearhead]

The requeueing endlessly  seems to have something to do with a deadlock... but I can't see which one or why (Dl still locked, pausing) and there is a hard limit on the amount of times something can be queued (Item queued too often, task cancelled:)

Does this always happen or just rarely? Any specific cases (while dl'ing sth else? updating? doing another nzb file? reading one? etc etc?)

[Reab4]

Its always. I just updated the db again:
alter table downloadinfo add column `subdl` tinyint(10) default 0 not null;

I purged the a.b.m.cooking and updated again. Still the 'waited too long error' and urdd shutdown.

Perhaps the upatedb doesn't work and I need to re-build the db from scratch?

Edit:
I removed the .installed and rebuild the db. It works fine now.
Sorry for the harassment

I noticed something odd though:
'import all settings' resulted in log-in window again. After logging in again, the newsgroup list was not imported. I could however import the 'urd_all_settings' into the Subscriptions>Newsgroups>import groups.

[spearhead]

It seems you missed the lock in the db then.

I'll look into the import settings thing again. Tricky code that is.

[fzeroe]

I also got this problem after svn 1500, hadn't updated urd in a while...

I also tried to update the DB but still got the same errors


FzeroE
 

[spearhead]

The lock was added in 0..6.1 So you may have to run all the sql files since then (starting with 0.6.0 to 0.6.1) in the install directory. Or you just may have missed one.

Note the update.sh will terminate on error. Run each of the files like
mysql -u USER -p urddb < update_XXX_mysql.sql
(fill in USER and XXX, urddb is the default table name, but it may be different, check dbconfig.php)

[fzeroe]

i removed .installed and restarted

But i can't import settings i get a class error

[thorwak]

Spearhead really makes a great job trying to help ppl, even those on SVN code. But let's face it - SVN is work in progress. It's often broken one way or the other, that's why it's not released yet. It's great that ppl want to try it, and the more testers the better. However - don't run it on production DBs! Don't expect it to be easy to use or that you can just overwrite your existing installation and keep running as if nothing happened.

Test SVN separately, and if you find a broken behavior you should be prepared to at least try to dive into the code yourself and try to identify and perhaps even fix the problem, providing a patch. Such work would be very welcomed!

If you're mostly interested in having stuff work as well as possible, run the stable version (1.0.4 now).

1.0.5 will bring some new cool stuff, but if you decide to run svn (I'm not directing this to anyone in particular, just general advice since most ppl seem to be on svn now ) be prepared to find it's broken and try to identify problems rather than just saying that something is weird one way no another.

If that fails, after you've tried, one can at least report what steps has been taken to try so see what's going on since that may save time for (mainly) Spearhead to find the underlying problem.

Now, Spearhead may not agree with what I just said above, and should then overrule all I said, and I'll stand in the corner looking stupid 

[spearhead]

i removed .installed and restarted

But i can't import settings i get a class error

Can you post the error?

And I concur with Thorwak mostly. Even though svn should work fine, it hasn't been tested properly. Hence I use svn for my normal use as well. Finding most problems that way.

Anyway, if you got a problem with any version, just post and I'll try and help.

[fzeroe]

Everything you say is so true and i never expect a solution when using an svn version.
But spearhead can mostly point us in the right direction.
And other ppl can gets hints of a problem if someone else asks about it.
And there is no stupid questions. So just ask away.

FzeroE
 

[fzeroe]

Sure when importing a xml user settings to the recreated user i get this error
I get the same error when trying import a configuration export.

Message:
Class not found

Nothing in the logs

[spearhead]

Sure when importing a xml user settings to the recreated user i get this error
I get the same error when trying import a configuration export.

Message:
Class not found

Nothing in the logs

I can't fix it here, but I made a change in the error msg. Can you svn up and try again? It should print the classname now. Probably a silly typo somewhere.

[thorwak]

I'm glad we're on the same page. I really wasn't trying to criticize, more hint towards newcomers that getting SVN, if not wanting to experiment, may not always be the way to go. I'm glad it was received the way I tried to express it


ontopic: I had a kernel oops in a VM (running experimental kernel so not surprised) leading to a cold boot of that VM. urdd was in the process of unraring at this point, over NFS, and this lead to a partly extracted file being left sitting there.

When I got the URD VM up again, "downloads" show this download (correctly) as "unpacking failed" (or sth, I run in Swedish these days ). When I try to unrar again from the UI, repeatedly, it fails, because rar reports there is nothing to extract. After some investigation, this was because of the partly extracted file already being there, and unrar decided there was no new work to be done. When I renamed that partly extracted file, extraction worked again as expected from the UI.

Before rename:

RAR 3.80 beta 3   Copyright (c) 1993-2008 Alexander Roshal   10 Jul 2008
Shareware version         Type RAR -? for help
Extracting from ./some.file-somegroup.r03
Extracting from ./some.file-somegroup.rar
Extracting from ./some.file-somegroup.r00
Extracting from ./some.file-somegroup.r01
.
.
.
Extracting from ./some.file-somegroup.r22
No files to extract

After rename/removal of partly extracted file (remains from crash):

RAR 3.80 beta 3   Copyright (c) 1993-2008 Alexander Roshal   10 Jul 2008
Shareware version         Type RAR -? for help

Extracting from ./some.file-somegroup.r03
Extracting from ./some.file-somegroup.rar
Extracting  some.file.extracted.name-somegroup.mkv              
Extracting from ./some.file-somegroup.r00
...         some.file.extracted.name-somegroup.mkv              
Extracting from ./some.file-somegroup.r01
...         some.file.extracted.name-somegroup.mkv              
Extracting from ./some.file-somegroup.r02
.
.
.
...         some.file.extracted.name-somegroup.mkv              

Extracting from ./some.file-somegroup.r22

...         some.file.extracted.name-somegroup.mkv                 OK
All OK

I guess this has to do with the options passed to (un)rar, to not overwrite?. I'm not sure how it should be addressed best - it's neat that it doesn't do it all over again when one wants to just check for new subs or whatever, but it also breaks situations where the unrar failed for some reason (crash, nfs share going away temporarily or whatever). Agreed, it's an abnormal situation, but would be nice if it could be handled in a neat way.

(on svn 1504)

[spearhead]

The crude way to do this is use the unrar_pars option in admin/config.

Maybe there is some cool option with rar or another rar compatible decompressor (eg 7z). I don't really see an easy way to do this. But I think it could be done nonetheless. Imo tho, those are just rare occasions.

[thorwak]

I agree, this is not something to prioritize. I guess one workaround could be:

Check if there are any common file types already there (.iso, .img, .avi and so on) If so, AND if unrar returns with "no files to extract", re-run rar with overwrite flag set (I guess there is one, but haven't checked). One could also delete any such files already present, but that could misfire, so better to let unrar overwrite any files with same names.

One of those things to implement when having half an hour to kill, if feeling like it (May do it myself, perhaps)

EDIT: Forgot the most important thing: The total size of the pre-existing file(s) should not be a lot less than total size of .rars Otherwise it would trigger every time..

[spearhead]

Or run RAR -l (or whatever) and get the filelist. then compare that with what is on disk, do a cleanup and then rar. But that is a lot of work.

Any other approach could easily lead to deleting files. Some post contain multiple rars or rars in rars or contain non rarred files, eg sample videos.

You can always delete the file(s) and re-run rar manually from within URD

[thorwak]

Yeah it's easy to solve, it's just that one might not understand what's happening