Plugin: SJQv4

[Slugger]

Originally Posted by toricred

I looked all the way back to sagetv3.txt and it is still only through today.

Wouldn't your changes fail to get all segments if called on a non-live multi-segment file?

Yes. But it will allow me to test my theory about Groovy executing processes.

Also, you say the UI hangs. Just the SJQ UI or the entire Sage UI, requiring a restart of the Client/extender? You already said that the server continues on with recordings fine, etc. so I'm wondering if it's just the SJQ UI that "hangs". If so, do you just mean the queue no longer loads up, etc. but you can still back out and then go watch a recording or whatever?

It's unfortunate that the Sage logs don't go back far enough. Because I'm really stumped as to the cause. You don't have to change to the split test/task yet, but then we're in a holding pattern until we get some sage logs for this problem.

[toricred]

It's just the SJQ UI that hangs. Once I go to look at queue or completed tasks I have to restart the extender to stop the spinning circle.

[toricred]

I could go ahead and break up the task now if it will help with finding, but it won't be until tomorrow night.

[Slugger]

Originally Posted by toricred

It's just the SJQ UI that hangs. Once I go to look at queue or completed tasks I have to restart the extender to stop the spinning circle.

Hmm... ok that points to an SJQ thread crashing, which is more in line with what we're seeing (i.e. the logs just stop at 19:00).

Originally Posted by toricred

I could go ahead and break up the task now if it will help with finding, but it won't be until tomorrow night.

Let's leave it like it is for now and gather up the sage debug logs the next time it happens. Hopefully those logs will be able to tell us more.

[K O]

I installed the latest version of SageTV Beta 7.1 and since then I cannot get the SJQ4 plugin to start. Per the log, it's having an issue accessing the database. It does this every 30 seconds. I have tried removing all my plugins and starting over, but it doesn't seem to correct it. Something is missing, but not sure what. Any advice on how to fix it?

2011-03-09 20:06:41,453 WARN [DataStore]: Problem connecting to database... trying again in 30 seconds...
2011-03-09 20:07:11,453 FATAL [DataStore]: H2 JDBC driver is missing!
java.lang.ClassNotFoundException: org.h2.Driver
at java.net.URLClassLoader$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
at java.lang.ClassLoader.loadClassInternal(Unknown Source)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Unknown Source)
at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:143)
at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:59)
at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:66)
at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:62)
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:99)
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.a.m$b.a(Unknown Source)
at sage.a.m.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.bd.a(Unknown Source)
at sage.bd.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.e$2.run(Unknown Source)
at sage.cz$a.run(Unknown Source)

[Slugger]

The sagex-h2 plugin is corrupted. Sage probably thinks it's installed but the jar file is missing. Uninstall the sagex-h2 plugin and reinstall it (you'll have to uninstall all the plugins that depend on it first). To confirm, check to see if Sage thinks that plugin is installed. If Sage thinks it is, go to SageTV/JARs/ and look for h2-1.2.xxx.jar. That jar is missing probably and that's the problem.

[K O]

The JAR file did exist (h2-1.2.145.jar), but I uninstalled the plugin dependencies and eventually the H2 plugin. At that point the JAR did not exist, and I restarted SageTV.

I then re-installed SJQ plugin from the interface and it downloaded all the dependencies, but it's still throwing the same error:

011-03-09 20:22:41,671 FATAL [DataStore]: H2 JDBC driver is missing!
java.lang.ClassNotFoundException: org.h2.Driver
at java.net.URLClassLoader$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source)
at java.lang.ClassLoader.loadClass(Unknown Source)
at java.lang.ClassLoader.loadClassInternal(Unknown Source)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Unknown Source)
at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:143)
at com.google.code.sagetvaddons.sjq.server.DataStore.<init>(DataStore.java:59)
at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:66)
at com.google.code.sagetvaddons.sjq.server.DataStore$1.initialValue(DataStore.java:62)
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:85)
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.a.m$b.a(Unknown Source)
at sage.a.m.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.bd.a(Unknown Source)
at sage.bd.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.e.a(Unknown Source)
at sage.e$2.run(Unknown Source)
at sage.cz$a.run(Unknown Source)
2011-03-09 20:22:41,671 WARN [DataStore]: Problem connecting to database... trying again in 1 seconds...

[Slugger]

Are there duplicate jars in the JARs folder? So like h2-1.2.145.jar and "Copy of h2-1.2.145.jar"? Or two different versions of h2 (like h2-1.2.145.jar and h2-1.2.139.jar). If the jar is there and you still get this error then it's likely duplicate jars. If you don't see any duplicates then I need to see the sage debug logs (specifically, the classpath setting towards the top of the file when starting up SageTV).

[K O]

There is only the single h2-1.2.145.jar file, no 'copy of' or variants that start with 'h2'.

I'm not sure what file you are referring to needing the classpath from.

[Slugger]

Originally Posted by K O

I'm not sure what file you are referring to needing the classpath from.

Enable sagetv debug logging, restart sagetv and send me your sagetv_0.txt log file after sage has started back up.

[K O]

classpath=C:\Program Files\SageTV\SageTV\Sage.jar;C:\Program Files\SageTV\SageTV\xerces.jar;C:\Program Files\SageTV\SageTV\plugin.jar;C:\Program Files\SageTV\SageTV\;;JARs\ant-1.6.5.jar;JARs\commons-codec-1.3.jar;JARs\commons-dbutils-1.3.jar;JARs\commons-io-1.4.jar;JARs\commons-jxpath-1.1.jar;JARs\commons-lang-2.4.jar;JARs\commons-net-1.4.1.jar;JARs\core-3.1.1.jar;JARs\cron4j-2.2.1.jar;JARs\dom4j-1.6.1.jar;JARs\gkusnick.sagetv.jar;JARs\h2-1.2.145.jar;JARs\jcifs-1.1.6.jar;JARs\jdic.jar;JARs\jetty-6.1.19.jar;JARs\jetty-ajp-6.1.19.jar;JARs\jetty-rewrite-handler-6.1.19.jar;JARs\jetty-sslengine-6.1.19.jar;JARs\jetty-starter.jar;JARs\jetty-util-6.1.19.jar;JARs\jsp-2.1-jetty-6.1.19.jar;JARs\jsp-2.1.jar;JARs\jsp-api-2.1.jar;JARs\log4j-1.2.15.jar;JARs\phoenix.jar;JARs\sagex-api.jar;JARs\sagex-h2.jar;JARs\salicense.jar;JARs\sbbi-upnplib-1.0.3.jar;JARs\servlet-api-2.5-6.1.19.jar;JARs\sjq-common.jar;JARs\sjq-listener.jar;JARs\sjq.jar;JARs\somf.jar;JARs\vecmath.jar

[Slugger]

Looks ok to me. The h2-1.2.145.jar is in the classpath, which means it should be loaded up by Sage. So either the h2 jar file is corrupted (what's the file's timestamp and size?) or there's something wrong with the Sage classloader. If the jar isn't corrupted then I'm afraid you'll have to perhaps follow up with Sage support because the usual culprits don't seem to apply here and I can't reproduce the issue locally to attempt further investigation.

[K O]

1,176 KB
11/14/2010 10:22 AM

[Slugger]

Looks good. I'm afraid I don't have an answer and am out of ideas. The jar is in the classpath, Sage is therefore presumably loading it, but it fails to find the JDBC driver class when requested by the SJQ plugin code.

You say you upgraded to the latest beta? Which version? 7.1.3? If so, I'd try moving back to 7.1.2 and see if that solves the issue. If so, then I'd definitely say it's a Sage core classloader bug/issue.

[K O]

I was on 7.1.2 and I upgraded to 7.1.3. just now and it started working again.

Whatever was broken is now fixed.

Thanks for walking me through the steps to fix it.

[Slugger]

Originally Posted by K O

I was on 7.1.2 and I upgraded to 7.1.3. just now and it started working again.

Whatever was broken is now fixed.

Thanks for walking me through the steps to fix it.

Didn't really do much.

Glad you're up and running again, but I really hate unexplained, "magical" fixes. Seems something somewhere is broken and is likely to pop up again down the road (if not for you, then somebody else). Perhaps a corrupted 7.1.2 install? Who knows? Anyway, glad it's fixed.

[K O]

Fixed seems like a relative term. It no longer says "Failed" on the plugin itself, but it doesn't seem to be actually executing Comskip.

Here's the last few entries for sjq.log:

2011-03-10 12:49:27,197 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:49:38,384 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:49:46,384 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:49:46,400 INFO  [TaskQueue]: Assigned task 1 of type 'COMSKIP1' to Client[host=whs:23344,state=ONLINE,lastUpdate=Thu Mar 10 12:49:46 CST 2011]
2011-03-10 12:49:46,400 INFO[ListenerClient]: Disconnected from whs:23344
2011-03-10 12:49:46,884 INFO[Listener]: Received connection from: /192.168.1.99:4628
2011-03-10 12:49:48,150 ERROR [Handler]: IOError: 192.168.1.99:4628
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)
2011-03-10 12:49:48,150 INFO[Listener]: Received connection from: /192.168.1.99:4630
2011-03-10 12:49:48,150 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.99:4630
2011-03-10 12:49:48,197 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4630
2011-03-10 12:49:48,197 INFO[Listener]: Received connection from: /192.168.1.99:4632
2011-03-10 12:49:48,197 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.99:4632
2011-03-10 12:49:48,213 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:49:48,213 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4632
2011-03-10 12:49:56,213 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:50:08,384 WARN  [AgentManager]: License server response: Cannot read specified license file! [C:\Program Files\SageTV\SageTV\plugins\sagetv-addons.lic]
2011-03-10 12:50:08,384 INFO  [AgentManager]: Pinging Client[host=whs:23344,state=ONLINE,lastUpdate=2011-03-10 12:49:46.384]
2011-03-10 12:50:08,384 INFO[ListenerClient]: Disconnected from whs:23344
2011-03-10 12:50:08,384 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:50:16,384 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:50:16,400 INFO  [TaskQueue]: Assigned task 1 of type 'COMSKIP1' to Client[host=whs:23344,state=ONLINE,lastUpdate=Thu Mar 10 12:50:16 CST 2011]
2011-03-10 12:50:16,400 INFO[ListenerClient]: Disconnected from whs:23344
2011-03-10 12:50:17,009 INFO[Listener]: Received connection from: /192.168.1.99:4642
2011-03-10 12:50:18,884 ERROR [Handler]: IOError: 192.168.1.99:4642
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)
2011-03-10 12:50:18,900 INFO[Listener]: Received connection from: /192.168.1.99:4647
2011-03-10 12:50:18,900 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.99:4647
2011-03-10 12:50:18,931 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4647
2011-03-10 12:50:18,931 INFO[Listener]: Received connection from: /192.168.1.99:4649
2011-03-10 12:50:18,931 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.99:4649
2011-03-10 12:50:18,947 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:50:18,947 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4649
2011-03-10 12:50:26,947 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:50:38,384 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:50:46,384 INFO  [TaskQueue]: Running queue processor now!
2011-03-10 12:50:46,400 INFO  [TaskQueue]: Assigned task 1 of type 'COMSKIP1' to Client[host=whs:23344,state=ONLINE,lastUpdate=Thu Mar 10 12:50:46 CST 2011]
2011-03-10 12:50:46,400 INFO[ListenerClient]: Disconnected from whs:23344
2011-03-10 12:50:46,994 INFO[Listener]: Received connection from: /192.168.1.99:4655
2011-03-10 12:50:48,134 ERROR [Handler]: IOError: 192.168.1.99:4655
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)
2011-03-10 12:50:48,134 INFO[Listener]: Received connection from: /192.168.1.99:4657
2011-03-10 12:50:48,134 INFO  [Handler]: CMD: LOGTEST :: PEER: /192.168.1.99:4657
2011-03-10 12:50:48,150 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4657
2011-03-10 12:50:48,150 INFO[Listener]: Received connection from: /192.168.1.99:4659
2011-03-10 12:50:48,150 INFO  [Handler]: CMD: UPDATE :: PEER: /192.168.1.99:4659
2011-03-10 12:50:48,150 INFO  [TaskQueue]: Scheduling queue processor for ~8 seconds from now!
2011-03-10 12:50:48,150 INFO  [Handler]: CMD: QUIT :: PEER: /192.168.1.99:4659
2011-03-10 12:50:52,150 INFO  [Plugin]: Event received: MediaFileImported
2011-03-10 12:50:52,275 INFO  [Plugin]: Event received: MediaFileImported

[Slugger]

It's assigning the task to the client, so let's see sjqagent.log (in SageTV/plugins/sjq-agent/logs/).

[K O]

Originally Posted by Slugger

It's assigning the task to the client, so let's see sjqagent.log (in SageTV/plugins/sjq-agent/logs/).

I'm running the service client rather than the plugin, but I assume it's the same log:

2011-03-10 12:55:46,384 INFO [Exe]: Received task 1 of type 'COMSKIP1' from 192.168.1.99:23347...
2011-03-10 12:55:46,384 INFO [192_168_1_99-23347-1]: Starting process runner for: Task[id=COMSKIP1, reqRes=50, maxInst=2, sched=ON, maxTime=28800, maxTimeRatio=1.0, rc=0-2, exe=c:/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=c:/sjqagent/comskip_test.groovy, testArgs=mpg]
2011-03-10 12:55:49,197 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:55:49,213 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:55:49,213 WARN [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-1
2011-03-10 12:56:16,384 INFO [Exe]: Received task 1 of type 'COMSKIP1' from 192.168.1.99:23347...
2011-03-10 12:56:16,384 INFO [192_168_1_99-23347-1]: Starting process runner for: Task[id=COMSKIP1, reqRes=50, maxInst=2, sched=ON, maxTime=28800, maxTimeRatio=1.0, rc=0-2, exe=c:/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=c:/sjqagent/comskip_test.groovy, testArgs=mpg]
2011-03-10 12:56:18,306 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:56:18,322 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:56:18,322 WARN [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-1
2011-03-10 12:56:46,384 INFO [Exe]: Received task 1 of type 'COMSKIP1' from 192.168.1.99:23347...
2011-03-10 12:56:46,384 INFO [192_168_1_99-23347-1]: Starting process runner for: Task[id=COMSKIP1, reqRes=50, maxInst=2, sched=ON, maxTime=28800, maxTimeRatio=1.0, rc=0-2, exe=c:/comskip/comskip.exe, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=c:/sjqagent/comskip_test.groovy, testArgs=mpg]
2011-03-10 12:56:49,291 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:56:49,306 INFO[ListenerClient]: Disconnected from 192.168.1.99:23347
2011-03-10 12:56:49,306 WARN [ProcessRunner]: Removing task from active list: SJQ4Task-192.168.1.99-23347-1

[Slugger]

Nothing unusual there. Looks like the test script is returning a failure. Take a look at the task output from the STV UI. Does it shed any light?