Plugin: SJQv4

[Slugger]

It is with great pleasure that I announce the first public beta of SJQv4. Many of the highlights of this release have been discussed (in the early part) of this preview thread.

Some of the important things to realize before installing/upgrading:

• SJQv4 requires a sagetv-addons license file to unlock all features! If you currently have SJQv3 installed then upgrading is final and there is no turning back (SageTV plugin manager restriction, not mine). If you do not wish to donate then do NOT upgrade. There are alternatives to donating if you wish to unlock all features. Those alternatives are discussed in the project's donations FAQ.
• If you wish to use the task client (agent) plugin, it must be installed separately. It will NOT be installed automatically with the engine. A standalone console (all platforms) and Windows service version of the task client are also available for separate download outside of the plugin manager. The user guide discusses those installation options in detail.
• There is currently no web UI for SJQv4. There is an STVi plugin available and it must be installed separately. The UI mod can be installed on a server, client, or extender. (NOTE: The UI plugin may not be available right away. I've given the green light to tmiranda to add it to the repository, it's just a matter of when he reads his email again).
• The User Guide is available, but not complete. This release is kind of at a bad time with it being the holiday season and everything. After some discussions, we've elected to release beta 1 as is and will continue to fill in the docs during the holidays as time permits. There is plenty of documentation available, including a complete example on how to setup comskip under SJQv4. Obviously, ask questions as necessary.
• Keep the feedback coming, but be aware that during this holiday time, feature requests will probably be low priority and so will minor bug reports. We definitely will track them all, but only major issues will be addressed over the next few weeks. I'll be back into dev mode after the new year.

SJQv4 is a rather big shift in task automation for the SageTV platform. Those coming from SJQv3 (and older) should be able to adjust with little (but some) effort. For new users, there is definitely a learning curve, but if you're willing to put in the time then I believe you'll find SJQv4 to be a very, very powerful tool.

Note to SJQv3 Users: With this release, I officially no longer support SJQv3 (or older). SJQv4 is now the preferred, supported and recommended release.

EDIT: The non licensed version restricts users to a single task client capable of running only one configured task. The unlicensed version is functional, with those restrictions.

[tmiranda]

The SJQ UI is also available in the repository.

Wiki here: http://code.google.com/p/tmiranda/wi...4UserInterface

[bikesquid]

Thanks for the update. I unfortunately got twitchy and hit the update button before reading. So I'm trying to make the best of it and get it all working. I've got the server/client pieces installed and client is showing online. Using the provided comskip test script and I'm getting 'returned' for the task state and though it seems an obvious state, I'm not sure what to do about it, logs say they are empty so no help there. Suggestions?

[Slugger]

Originally Posted by bikesquid

Thanks for the update. I unfortunately got twitchy and hit the update button before reading. So I'm trying to make the best of it and get it all working. I've got the server/client pieces installed and client is showing online. Using the provided comskip test script and I'm getting 'returned' for the task state and though it seems an obvious state, I'm not sure what to do about it, logs say they are empty so no help there. Suggestions?

Seems like it's a problem with the location of the .groovy script. Have a look in SageTV\plugins\sjq\sjq.log and see if there are any errors reported in there.

[bikesquid]

Originally Posted by Slugger

Seems like it's a problem with the location of the .groovy script. Have a look in SageTV\plugins\sjq\sjq.log and see if there are any errors reported in there.

First of all, I can see how this will be more powerful a tool, I like (assuming it starts to work)!

Second, the last section in the sjq.log is telling me there aren't enough free resources to perform the task..... I checked the client and it's setup for 100 total and shows 100 available. Under active tasks it shows 4 instances of the comskip script w/ 'returned' as the status. based on the created time of the first instance of the task, here's that section from the log, and below that, the last part of the log. Thanks for the help!

2010-12-12 22:10:41,332 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:10:41,654 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:10:41,855 INFO  [Handler]: CMD: PINGC :: PEER: /127.0.0.1
2010-12-12 22:10:41,856 INFO  [AgentManager]: Pinging Client[host=Master-PC:23344,state=ONLINE,lastUpdate=2010-12-12 22:09:33.646]
2010-12-12 22:10:41,865 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:10:45,720 INFO  [Handler]: CMD: ADDTASK :: PEER: /127.0.0.1
2010-12-12 22:10:45,730 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:10:45,751 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:10:51,998 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:10:53,731 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:10:53,834 INFO  [TaskQueue]: Assigned task 1 of type 'HDCOMSKIP' to Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Sun Dec 12 22:10:53 MST 2010]
2010-12-12 22:10:53,835 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:10:53,865 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-12 22:10:53,865 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-12 22:10:53,874 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:10:53,874 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-12 22:10:56,847 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:11:00,420 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:11:01,874 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:11:03,654 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:11:06,557 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:11:10,104 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:11:11,655 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:11:11,665 INFO  [TaskQueue]: Assigned task 1 of type 'HDCOMSKIP' to Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Sun Dec 12 22:11:11 MST 2010]
2010-12-12 22:11:11,665 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:11:11,737 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-12 22:11:11,737 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-12 22:11:11,747 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:11:11,747 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-12 22:11:15,146 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:11:19,747 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:11:23,280 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:11:26,530 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:11:28,316 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:11:28,975 INFO  [Handler]: CMD: QUIT :: PEER: /127.0.0.1
2010-12-12 22:11:33,644 INFO  [AgentManager]: Pinging Client[host=Master-PC:23344,state=ONLINE,lastUpdate=2010-12-12 22:11:11.657]
2010-12-12 22:11:33,647 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:11:33,654 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:11:35,562 INFO  [Listener]: Received connection from: /127.0.0.1
2010-12-12 22:11:41,654 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:11:41,663 INFO  [TaskQueue]: Assigned task 1 of type 'HDCOMSKIP' to Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Sun Dec 12 22:11:41 MST 2010]
2010-12-12 22:11:41,663 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:11:41,681 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-12 22:11:41,681 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-12 22:11:41,690 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:11:41,690 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-12 22:11:49,691 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:11:50,557 INFO  [Handler]: CMD: PINGC :: PEER: /127.0.0.1
2010-12-12 22:11:50,559 INFO  [AgentManager]: Pinging Client[host=Master-PC:23344,state=ONLINE,lastUpdate=2010-12-12 22:11:33.647]
2010-12-12 22:11:50,569 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:12:03,669 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-12 22:12:11,669 INFO  [TaskQueue]: Running queue processor now!
2010-12-12 22:12:11,680 INFO  [TaskQueue]: Assigned task 1 of type 'HDCOMSKIP' to Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Sun Dec 12 22:12:11 MST 2010]
2010-12-12 22:12:11,680 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-12 22:12:11,684 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-12 22:12:11,684 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-12 22:12:11,694 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds

"2010-12-13 07:57:12,108 WARN  [TaskQueue]: Client does not have enough free resources to perform this task! [0 < 100]; skipping: Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Mon Dec 13 07:57:12 MST 2010]
2010-12-13 07:57:12,108 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-13 07:57:12,108 WARN  [TaskQueue]: No clients available to accept task of type 'HDCOMSKIP'"

[bikesquid]

And on a related subject, how can I completely remove sjq 3.x server/client (service version)? I recall seeing something on the subject, but can't find it now when I need it.... Thanks!

[Slugger]

Originally Posted by bikesquid

And on a related subject, how can I completely remove sjq 3.x server/client (service version)? I recall seeing something on the subject, but can't find it now when I need it.... Thanks!

The server was removed/upgraded when you upgraded to v4 so nothing to do there. The task client can be removed by stopping the service then going to the directory where you installed the task client and running the uninstall bat file.

As to the problem, zip and attach the entire log file. Is there more than one task in the queue right now? Not having enough resources could just mean there's already too many tasks running. "0 < 100" means there are no free resources and you require 100 to run the task. So it seems there's another task using all 100 resources. If there were more than 1 task of the same type in the queue then that would happen; the first task would be assigned and consume all 100 resources while the others in the queue would produce the error ("not enough resources").

[voidpt]

Just testing out SJQv4 for the first time. Been using SJQv3 until now, thanks for a great product

But having problems getting SJQv4 up and running at all. But public-beta is what it is. And SageTV wouldn't be SageTV without initial issues

This is on a relatively clean 7.0.23 SageTV install. SJQv3 has not been installed at all on this installation. Problem is this. The install of the "Sage Job Queue (SJQ)" plugin goes ok, until the latest message:
» "Plugin Install Progress: Finalizing install: Sage Job Queue (SJQ)"
Here it stands in about 5min, until following message:
» "Plugin Install Progress: Done - OK"

At this point, I'm a little sceptical to the 'ok' message Taking my conlusion at once. Have had a look at the sjq.log file. A lot of these entries:
» 2010-12-13 18:45:33,851 FATAL [DataStore]: SQL Error
» org.h2.jdbc.JdbcSQLException: Syntax error in SQL statement "..."
» ...
» 2010-12-13 18:45:33,866 WARN [DataStore]: Problem connecting to database... trying again in 1 seconds...
Then I hit on a info statement on the "SageTV H2 Database" dependency plug-in:
» *Note: The default Tcp port for H2 conflicts with the default port for Squeeze box, so you must change the port on one of the plugins to allow both to be used.

And yes, I have SqueezeBox installed on my server. Also have MySQL/Apache. To try to problemsolve, I turned off SqueezeBox service (with its SQL), MySQL & Apache. Also turned of my ESET antivirus/firewall. But still, same behaviour. Even though I have backup/restore'ed the whole SageTV directory so no lingering stuff should be in the way the second time. Relatively clean install of SJQv4 each time.

Any tips ? Can I try to configure some stuff ? Change port of H2 DB ? Any more logs than sjq.log that can give me something ?

BTW: Here is one full entry of the repeating stuff in sjq.log, if it can give anything:

2010-12-13 18:50:05,142 FATAL [DataStore]: SQL Error
org.h2.jdbc.JdbcSQLException: Syntax error in SQL statement "CREATE TABLE IF NOT EXISTS CLIENT_TASKS (ID VARCHAR(128) NOT NULL, HOST VARCHAR(512) NOT NULL, PORT INT NOT NULL, REQD_RESOURCES TINYINT NOT NULL DEFAULT 100, MAX_INSTANCES TINYINT NOT NULL DEFAULT 1, SCHEDULE VARCHAR(256) NOT NULL DEFAULT 'ON', EXE VARCHAR(255) NOT NULL, ARGS VARCHAR(7936) NOT NULL DEFAULT '', MAX_TIME INT NOT NULL DEFAULT 86400, MAX_TIME_RATIO REAL NOT NULL DEFAULT 1,000000[*], MIN_RC SMALLINT NOT NULL DEFAULT 0, MAX_RC SMALLINT NOT NULL DEFAULT 0, TEST VARCHAR(255), TEST_ARGS VARCHAR(7936) NOT NULL DEFAULT '', PRIMARY KEY (ID, HOST, PORT), CONSTRAINT IF NOT EXISTS FK_CLIENT__CLIENT_TASKS FOREIGN KEY (HOST, PORT) REFERENCES CLIENT (HOST, PORT) ON DELETE CASCADE, CONSTRAINT IF NOT EXISTS ID_NOT_EMPTY__CLIENT_TASKS CHECK LENGTH(ID) > 0, CONSTRAINT IF NOT EXISTS MAX_INST_GE_ZERO__CLIENT_TASKS CHECK MAX_INSTANCES >= 0, CONSTRAINT IF NOT EXISTS REQ_RES_GE_ZERO__CLIENT_TASKS CHECK REQD_RESOURCES >= 0, CONSTRAINT IF NOT EXISTS MAX_TIME_GE_ZERO__CLIENT_TASKS CHECK MAX_TIME >= 0, CONSTRAINT IF NOT EXISTS MAX_TIME_RATIO_GE_ZERO__CLIENT_TASKS CHECK MAX_TIME_RATIO >= 0, CONSTRAINT IF NOT EXISTS MIN_RC_GE_ZERO__CLIENT_TASKS CHECK MIN_RC >= 0, CONSTRAINT IF NOT EXISTS MAX_RC_GE_ZERO__CLIENT_TASKS CHECK MAX_RC >= 0, CONSTRAINT IF NOT EXISTS MAX_RC_GE_MIN_RC__CLIENT_TASKS CHECK MAX_RC >= MIN_RC) "; expected "identifier"; SQL statement:
CREATE TABLE IF NOT EXISTS client_tasks (id VARCHAR(128) NOT NULL, host VARCHAR(512) NOT NULL, port INT NOT NULL, reqd_resources TINYINT NOT NULL DEFAULT 100, max_instances TINYINT NOT NULL DEFAULT 1, schedule VARCHAR(256) NOT NULL DEFAULT 'ON', exe VARCHAR(255) NOT NULL, args VARCHAR(7936) NOT NULL DEFAULT '', max_time INT NOT NULL DEFAULT 86400, max_time_ratio REAL NOT NULL DEFAULT 1,000000, min_rc SMALLINT NOT NULL DEFAULT 0, max_rc SMALLINT NOT NULL DEFAULT 0, test VARCHAR(255), test_args VARCHAR(7936) NOT NULL DEFAULT '', PRIMARY KEY (id, host, port), CONSTRAINT IF NOT EXISTS fk_client__client_tasks FOREIGN KEY (host, port) REFERENCES client (host, port) ON DELETE CASCADE, CONSTRAINT IF NOT EXISTS id_not_empty__client_tasks CHECK LENGTH(id) > 0, CONSTRAINT IF NOT EXISTS max_inst_ge_zero__client_tasks CHECK max_instances >= 0, CONSTRAINT IF NOT EXISTS req_res_ge_zero__client_tasks CHECK reqd_resources >= 0, CONSTRAINT IF NOT EXISTS max_time_ge_zero__client_tasks CHECK max_time >= 0, CONSTRAINT IF NOT EXISTS max_time_ratio_ge_zero__client_tasks CHECK max_time_ratio >= 0, CONSTRAINT IF NOT EXISTS min_rc_ge_zero__client_tasks CHECK min_rc >= 0, CONSTRAINT IF NOT EXISTS max_rc_ge_zero__client_tasks CHECK max_rc >= 0, CONSTRAINT IF NOT EXISTS max_rc_ge_min_rc__client_tasks CHECK max_rc >= min_rc) [42001-145]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:327)
	at org.h2.message.DbException.get(DbException.java:167)
	at org.h2.message.DbException.getSyntaxError(DbException.java:192)
	at org.h2.command.Parser.readColumnIdentifier(Parser.java:2650)
	at org.h2.command.Parser.parseCreateTable(Parser.java:4927)
	at org.h2.command.Parser.parseCreate(Parser.java:3661)
	at org.h2.command.Parser.parsePrepared(Parser.java:310)
	at org.h2.command.Parser.parse(Parser.java:274)
	at org.h2.command.Parser.parse(Parser.java:246)
	at org.h2.command.Parser.prepare(Parser.java:200)
	at org.h2.command.Parser.prepareCommand(Parser.java:213)
	at org.h2.engine.Session.prepareLocal(Session.java:423)
	at org.h2.server.TcpServerThread.process(TcpServerThread.java:226)
	at org.h2.server.TcpServerThread.run(TcpServerThread.java:137)
	at java.lang.Thread.run(Unknown Source)

	at org.h2.engine.SessionRemote.done(SessionRemote.java:543)
	at org.h2.command.CommandRemote.prepare(CommandRemote.java:68)
	at org.h2.command.CommandRemote.<init>(CommandRemote.java:47)
	at org.h2.engine.SessionRemote.prepareCommand(SessionRemote.java:421)
	at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1056)
	at org.h2.jdbc.JdbcStatement.executeUpdateInternal(JdbcStatement.java:122)
	at org.h2.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:111)
	at com.google.code.sagetvaddons.sjq.server.DataStore.initDb(DataStore.java:197)
	at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:146)
	at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:58)
	at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:65)
	at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:61)
	at java.lang.ThreadLocal.setInitialValue(Unknown Source)
	at java.lang.ThreadLocal.get(Unknown Source)
	at com.google.code.sagetvaddons.sjq.server.DataStore.get(DataStore.java:98)
	at com.google.code.sagetvaddons.sjq.server.Plugin.start(Plugin.java:268)
	at sage.plugin.a.a(Unknown Source)
	at sage.e.v$39.void(Unknown Source)
	at sage.ay.a(Unknown Source)
	at sage.e.a(Unknown Source)
	at sage.x.g(Unknown Source)
	at sage.x.f(Unknown Source)
	at sage.x.access$200(Unknown Source)
	at sage.x$3.run(Unknown Source)
	at sage.cv$a.run(Unknown Source)
2010-12-13 18:50:05,142 WARN  [DataStore]: Problem connecting to database... trying again in 30 seconds...

[Slugger]

@voidpt You can switch the port that H2 runs on by going to your plugin list, selecting the H2 plugin and configuring it.

However, the underlying problem is that your locale is confusing the H2 database. Your profile says you're from Norway and it appears in Norway a floating point number (like 1.23) is actually written as "1,23" in Norway (comma instead of period). Is this correct? Assuming that's the case, it appears H2 doesn't handle that so well and I will need to research a workaround for that. Please let me know.

[voidpt]

Originally Posted by Slugger

@voidpt You can switch the port that H2 runs on by going to your plugin list, selecting the H2 plugin and configuring it.

However, the underlying problem is that your locale is confusing the H2 database. Your profile says you're from Norway and it appears in Norway a floating point number (like 1.23) is actually written as "1,23" in Norway (comma instead of period). Is this correct? Assuming that's the case, it appears H2 doesn't handle that so well and I will need to research a workaround for that. Please let me know.

That was some quick observations, nice Yes, from Norway, and default Windows localization has:
» Region and Language / Additional Settings / Customize Format / [Numbers]
» » Decimal symbol: ","
I did a quick test with just this one single setting (changing to "."), without changing the whole localization / non-Unicode / keyboard (all Windows stuff). The one setting is not enough. But if I go all over (USA / English). Yup. Now it works without problems. Not gone through trying to find exactly how much must be changed. Unless you need it to pinpoint something.

And thanks for the config/H2 tip. Forgot that while testing.

No hurry. I can live without SJQv4 over the holidays. Just wanted to get started testing it. Should you need me to test anything though, just tell.

[Slugger]

Originally Posted by voidpt

That was some quick observations, nice Yes, from Norway, and default Windows localization has:
» Region and Language / Additional Settings / Customize Format / [Numbers]
» » Decimal symbol: ","
I did a quick test with just this one single setting (changing to "."), without changing the whole localization / non-Unicode / keyboard (all Windows stuff). The one setting is not enough. But if I go all over (USA / English). Yup. Now it works without problems. Not gone through trying to find exactly how much must be changed. Unless you need it to pinpoint something.

And thanks for the config/H2 tip. Forgot that while testing.

No hurry. I can live without SJQv4 over the holidays. Just wanted to get started testing it. Should you need me to test anything though, just tell.

I wouldn't worry about changing the locale on your system, I've forced locale to US/English in the Java code where necessary. I'm not sure if it'll work, but it should. I'll put a new build up shortly. Please let me know if it fixes the problem.

[bikesquid]

Originally Posted by Slugger

The server was removed/upgraded when you upgraded to v4 so nothing to do there. The task client can be removed by stopping the service then going to the directory where you installed the task client and running the uninstall bat file.

As to the problem, zip and attach the entire log file. Is there more than one task in the queue right now? Not having enough resources could just mean there's already too many tasks running. "0 < 100" means there are no free resources and you require 100 to run the task. So it seems there's another task using all 100 resources. If there were more than 1 task of the same type in the queue then that would happen; the first task would be assigned and consume all 100 resources while the others in the queue would produce the error ("not enough resources").

There ARE 4 instances of the same task assigned, but they all have a 'returned' state, so yes, that's likely why there's not enough resources, but why they're returned and not complete I don't understand or what to do about it... here's the log.

[bikesquid]

I love the idea of the option to view the task logs via the interface, but as a side note, the interface is telling me there are no info for the task. Don't know if that's the way it should work if I've got another problem too.... just an FYI.

[Slugger]

@bikesquid Thanks for posting the sjqagent.log file, that's actually the one I needed. Here's the problem:

2010-12-12 22:10:53,834 INFO  [192_168_1_110-23347-1]: Starting process runner for: Task[id=HDCOMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-0, exe=C:/Program Files/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=//Master-PC/C/Program_Files_(x86)/SageTV/scripts/comskip_test.groovy, testArgs=ts]
2010-12-12 22:10:53,863 ERROR [192_168_1_110-23347-1]: '\\Master-PC\C\Program_Files_(x86)\SageTV\scripts\comskip_test.groovy' does not exist or is not readable!  Test considered FAILED!

The comskip_test.groovy file is not where you told SJQ it would be or it can't be read by SJQ. Since it's located on a UNC path, is SageTV running as a user with proper network access? Is the path correct? That's why the tasks keep getting returned to the queue - the task client can't find the groovy script.

[Slugger]

Originally Posted by bikesquid

I love the idea of the option to view the task logs via the interface, but as a side note, the interface is telling me there are no info for the task. Don't know if that's the way it should work if I've got another problem too.... just an FYI.

Yeah, it's because the script is never running because it can't be found (see prev post for details). Once it actually is able to run then the output will be visible from the STV.

[bikesquid]

Originally Posted by Slugger

@bikesquid Thanks for posting the sjqagent.log file, that's actually the one I needed. Here's the problem:

2010-12-12 22:10:53,834 INFO  [192_168_1_110-23347-1]: Starting process runner for: Task[id=HDCOMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-0, exe=C:/Program Files/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=//Master-PC/C/Program_Files_(x86)/SageTV/scripts/comskip_test.groovy, testArgs=ts]
2010-12-12 22:10:53,863 ERROR [192_168_1_110-23347-1]: '\\Master-PC\C\Program_Files_(x86)\SageTV\scripts\comskip_test.groovy' does not exist or is not readable!  Test considered FAILED!

The comskip_test.groovy file is not where you told SJQ it would be or it can't be read by SJQ. Since it's located on a UNC path, is SageTV running as a user with proper network access? Is the path correct? That's why the tasks keep getting returned to the queue - the task client can't find the groovy script.

Is this maybe an issue with spaces in UNC paths? I think I had this problem in v3.x as well, but can't access that script since the upgrade, so can't check to see what I did to resolve the windows UNC vs the world's... I'm using _ in place of spaces, should that be different with this version?

[Slugger]

\\Master-PC\C\Program_Files_(x86)\SageTV\scripts\

Copy that path into a Windows Explorer window. If that path loads up and lists the groovy scripts in that folder then that's the value you should be using in SJQ. If there should be spaces instead of underscores in that directory path name then use spaces instead. Shouldn't be any issues with spaces in SJQ - use whatever you'd use in Windows Explorer to access the directory. SJQ uses the exact path you give it, verbatim. So it expects there to be a subdir names 'Program_Files_(x86)', if that's not the actual name of the dir then change it as necessary.

[bikesquid]

I guess I got carried away following the example EXACTLY to be safe... replaced the _ with spaces and it shows running! (but only for a moment) Then it goes back to showing returned...
Here's the client log's last few lines:

2010-12-13 14:48:36,557 INFO  [Exe]: Received task 7 of type 'HDCOMSKIP' from 192.168.1.110:23347...
2010-12-13 14:48:36,558 INFO  [192_168_1_110-23347-7]: Starting process runner for: Task[id=HDCOMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-0, exe=C:/Program Files/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=//Master-pc/c/Program Files (x86)/SageTV/scripts/comskip_test.groovy, testArgs=ts]
2010-12-13 14:48:38,157 INFO  [ListenerClient]: Disconnected from 192.168.1.110:23347
2010-12-13 14:48:38,167 INFO  [ListenerClient]: Disconnected from 192.168.1.110:23347
2010-12-13 14:48:38,167 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.110-23347-7
2010-12-13 14:49:06,558 INFO  [Exe]: Received task 7 of type 'HDCOMSKIP' from 192.168.1.110:23347...
2010-12-13 14:49:06,559 INFO  [192_168_1_110-23347-7]: Starting process runner for: Task[id=HDCOMSKIP, reqRes=100, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-0, exe=C:/Program Files/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=//Master-pc/c/Program Files (x86)/SageTV/scripts/comskip_test.groovy, testArgs=ts]
2010-12-13 14:49:07,534 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.1.110-23347-7) = true; [SJQ4Task-192.168.1.110-23347-7]
2010-12-13 14:49:08,161 INFO  [ListenerClient]: Disconnected from 192.168.1.110:23347
2010-12-13 14:49:08,171 INFO  [ListenerClient]: Disconnected from 192.168.1.110:23347
2010-12-13 14:49:08,171 WARN  [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.110-23347-7

and the server log

2010-12-13 14:51:08,160 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-13 14:51:08,160 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.110
2010-12-13 14:51:08,168 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-13 14:51:08,169 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-13 14:51:08,170 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-13 14:51:08,175 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-13 14:51:08,176 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-13 14:51:16,175 INFO  [TaskQueue]: Running queue processor now!
2010-12-13 14:51:28,553 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-13 14:51:36,553 INFO  [TaskQueue]: Running queue processor now!
2010-12-13 14:51:36,559 INFO  [TaskQueue]: Assigned task 7 of type 'HDCOMSKIP' to Client[host=Master-PC:23344,state=ONLINE,lastUpdate=Mon Dec 13 14:51:36 MST 2010]
2010-12-13 14:51:36,559 INFO  [ListenerClient]: Disconnected from Master-PC:23344
2010-12-13 14:51:37,001 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-13 14:51:38,063 ERROR [Handler]: IOError
java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.io.ObjectInputStream$PeekInputStream.peek(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.refill(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.read(Unknown Source)
    at java.io.DataInputStream.readUnsignedShort(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.readUnsignedShort(Unknown Source)
    at java.io.ObjectInputStream$BlockDataInputStream.readUTF(Unknown Source)
    at java.io.ObjectInputStream.readUTF(Unknown Source)
    at com.google.code.sagetvaddons.sjq.listener.Handler.run(Handler.java:62)
    at java.lang.Thread.run(Unknown Source)
2010-12-13 14:51:38,071 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-13 14:51:38,072 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.110
2010-12-13 14:51:38,090 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-13 14:51:38,091 INFO  [Listener]: Received connection from: /192.168.1.110
2010-12-13 14:51:38,091 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.110
2010-12-13 14:51:38,097 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2010-12-13 14:51:38,097 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.110
2010-12-13 14:51:46,097 INFO  [TaskQueue]: Running queue processor now!

On another note, I keep getting "schedule not valid" when trying to commit changes and have to re-enter ON even though it's already showing that.... I assume it should maintain the existing schedule if there is one, no?

[Slugger]

Ok, now go to the stv and look at the output for the task. Hopefully there's something there? Because now the task is running something so there should be some kind of output. You may also want to check for a log file generated by comskip, if it does that. Check the task output in the stv first. The connection reset exceptions aren't really an issue (well, I need to fix them, but they aren't really causing any problems, it's sort of normal behaviour).

As for the schedule problem, please open a ticket with the details. I don't handle UI issues, but will ensure it gets assigned to tmiranda for investigation.

[bikesquid]

Well, there's some log info, wish there was an easy way to cut/paste it, but here's the jist of it... LOG4j: Configured logging for:saex-api using file: sagex-api.log4j.properties javax.script.scriptexecption:java.lang.NumberFormatException: null.

it does that a few times.

Got a couple other questions about "how to" as well.

1) assuming I get the task running, is there an easy way to assign it to multiple clients, or do I have to rekey it as a new task for each client?

2) maybe this is a UI issue as well, but I select a client to 'see' what's going on and it asks me if I'm sure I want to delete the client... as I'm not using a remote, a mouse makes much more sense if select selects rather than deletes.... not sure if that's a question... other than in my mind....