Plugin: SJQv4

[bikesquid]

Originally Posted by Slugger

You said you were getting connection refused errors. I assume where ever you saw that error would also have a stack trace attached to it. Where are you seeing those errors logged?

I'm getting sage messages showing up from sjq4 I believe (deleted the messages) connection refused task client marked off line I believe, etc.

sjq has been unstable for a while, since a server rebuild/move. I've been just living with it and trying to sort one problem at a time but I think it's all related to this network loopback problem now.

I'm getting a lot of socket errors in the sjqagent.log

Here's one with the connection refused error:

axTime=86400, maxTimeRatio=1.0, rc=0-1, exe=script:\\Sage-pc\c\Program Files (x86)\SageTV\scripts\media_file_scanner.groovy, exeArgs=, test=, testArgs=]
2013-12-03 21:51:19,729 ERROR [192_168_0_111-23347-36198]: Failed to send task output to server!
java.net.ConnectException: Connection refused: connect
	at java.net.DualStackPlainSocketImpl.connect0(Native Method)
	at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source)
	at java.net.AbstractPlainSocketImpl.connect(Unknown Source)
	at java.net.PlainSocketImpl.connect(Unknown Source)
	at java.net.SocksSocketImpl.connect(Unknown Source)
	at java.net.Socket.connect(Unknown Source)
	at java.net.Socket.connect(Unknown Source)
	at java.net.Socket.<init>(Unknown Source)
	at java.net.Socket.<init>(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.ListenerClient.<init>(ListenerClient.java:41)
	at com.google.code.sagetvaddons.sjq.agent.network.ServerClient.<init>(ServerClient.java:30)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.runExe(ProcessRunner.java:212)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.run(ProcessRunner.java:168)
	at java.lang.Thread.run(Unknown Source)
2013-12-03 21:51:20,822 FATAL [192_168_0_111-23347-36198]: Failed to update Task[id=MEDIAFILESCANNER, reqRes=1, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=script:\\Sage-pc\c\Program Files (x86)\SageTV\scripts\media_file_scanner.groovy, exeArgs=, test=, testArgs=]
java.net.ConnectException: Connection refused: connect

and one with the connection reset error:

2013-12-03 21:50:06,205 WARN  [ProcessRunner]: isActive(SJQ4Task-192.168.0.111-23347-36196) = true; [SJQ4Task-192.168.0.111-23347-36196, SJQ4Task-192.168.0.111-23347-36194, SJQ4Task-192.168.0.111-23347-36130]
2013-12-03 21:50:37,493 ERROR [192_168_0_111-23347-36196]: Failed to send task output to server!
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(Unknown Source)
	at java.net.SocketInputStream.read(Unknown Source)
	at java.io.ObjectInputStream$PeekInputStream.read(Unknown Source)
	at java.io.ObjectInputStream$PeekInputStream.readFully(Unknown Source)
	at java.io.ObjectInputStream$BlockDataInputStream.readShort(Unknown Source)
	at java.io.ObjectInputStream.readStreamHeader(Unknown Source)
	at java.io.ObjectInputStream.<init>(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.ListenerClient.<init>(ListenerClient.java:44)
	at com.google.code.sagetvaddons.sjq.agent.network.ServerClient.<init>(ServerClient.java:30)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.runExe(ProcessRunner.java:212)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.run(ProcessRunner.java:168)
	at java.lang.Thread.run(Unknown Source)
2013-12-03 21:50:38,510 FATAL [192_168_0_111-23347-36196]: Failed to update Task[id=MEDIAFILESCANNER, reqRes=1, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=script:\\Sage-pc\c\Program Files (x86)\SageTV\scripts\media_file_scanner.groovy, exeArgs=, test=, testArgs=]
java.net.ConnectException: Connection refused: connect
	at java.net.DualStackPlainSocketImpl.connect0(Native Method)

and the one that throws the error to sage messages I think is this:

maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=script:\\Sage-pc\c\Program Files (x86)\SageTV\scripts\media_file_scanner.groovy, exeArgs=, test=, testArgs=]
2013-12-03 22:15:16,633 ERROR [192_168_0_111-23347-36200]: Failed to send logs to server!
java.net.SocketException: No buffer space available (maximum connections reached?): connect
	at java.net.DualStackPlainSocketImpl.connect0(Native Method)
	at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source)
	at java.net.AbstractPlainSocketImpl.connect(Unknown Source)
	at java.net.PlainSocketImpl.connect(Unknown Source)
	at java.net.SocksSocketImpl.connect(Unknown Source)
	at java.net.Socket.connect(Unknown Source)
	at java.net.Socket.connect(Unknown Source)
	at java.net.Socket.<init>(Unknown Source)
	at java.net.Socket.<init>(Unknown Source)
	at com.google.code.sagetvaddons.sjq.listener.ListenerClient.<init>(ListenerClient.java:41)
	at com.google.code.sagetvaddons.sjq.agent.network.ServerClient.<init>(ServerClient.java:30)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.runScriptTest(ProcessRunner.java:264)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.runTest(ProcessRunner.java:244)
	at com.google.code.sagetvaddons.sjq.agent.ProcessRunner.run(ProcessRunner.java:147)
	at java.lang.Thread.run(Unknown Source)
2013-12-03 22:15:16,637 FATAL [192_168_0_111-23347-36200]: Failed to update Task[id=RENAMECOMSKIP, reqRes=25, maxInst=1, sched=ON, maxTime=86400, maxTimeRatio=1.0, rc=0-1, exe=script:\\Sage-pc\c\Program Files (x86)\SageTV\scripts\rename_comskip.groovy, exeArgs="$SJQ4_PATH\$SJQ4_LAST_SEGMENT", test=\\Sage-pc\c\Program Files (x86)\SageTV\Scripts\Safe_to_Rename_test.groovy, testArgs=]
java.net.SocketException: No buffer space available (maximum connections reached?): connect
	at java.net.DualStackPlainSocketImpl.connect0(Native Method)
	at java.net.DualStackPlainSocketImpl.socketConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source)
	at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source)

[Slugger]

http://support.microsoft.com/kb/2577795

You may need that hotfix. Looking less and less like an SJQ/Java issue and more a Windows 7 issue.

[bikesquid]

That sounds vaguely familiar. Back in the fur of my memory. I'll give it a go and report back in case it's a solution that others could benefit from. Thx again Slugger for taking a look. The time and effort, as always, greatly appreciated. Hope this fixes it!

[wayner]

While Googling "Sage Groovy" - this came up - a Groovy Girl named Sage. Perhaps this should be the SJQ mascot?

[ptaylor]

Earlier tonight, I had my first decent sized batch of recordings (4) since setting up SJQ4 to move my recordings to my NAS. The first one it tried to move failed. It complained about not being able to delete the file (though I since deleted the task so I don't have the task log to show here). I suspect that the source file was being ComSkipped, as that's handled through the CommercialDetector plugin. Perhaps I need to disable this plugin and set SJQ4 to schedule comskip too. If so, I'm guessing I'd need to comskip before moving the file. ??

Anyhow, I now have two tasks that are just in WAITING. It's been like 30 minutes. I've been expecting them to go to another status at some point, even if it is just to RETURNED, but it doesn't seem to be kicking off to even run the test scripts... Any ideas?

Edit: Stopped/Restarted the SageTV Service and these started processing.

[Slugger]

Originally Posted by ptaylor

Earlier tonight, I had my first decent sized batch of recordings (4) since setting up SJQ4 to move my recordings to my NAS. The first one it tried to move failed. It complained about not being able to delete the file (though I since deleted the task so I don't have the task log to show here). I suspect that the source file was being ComSkipped, as that's handled through the CommercialDetector plugin. Perhaps I need to disable this plugin and set SJQ4 to schedule comskip too. If so, I'm guessing I'd need to comskip before moving the file. ??

It would make life easier if you used SJQ to run comskip too, but it's not totally necessary. If you don't make the switch, you just have to tighten up your pretest script to ensure it doesn't try to move anything until you're certain the file can be moved (or modifying/enhancing the archiving script to better handle locked files; the former being much easier a scenario to handle, imho). Doing comskip within SJQ makes this task much, much easier. The flip side being that triggering comskip in SJQ is much, much harder than just using the ComDetector plugin (I imagine, I've never actually used it). So it comes down to your comfort level with SJQ.

Anyhow, I now have two tasks that are just in WAITING. It's been like 30 minutes. I've been expecting them to go to another status at some point, even if it is just to RETURNED, but it doesn't seem to be kicking off to even run the test scripts... Any ideas?

Most likely the queue processor thread crashed; probably an NPE bug caused by removing the task from the queue. Do you see any stack traces in sjq.log or in sagetv_0.txt? Unlikely I'd fix such a bug at this point, but definitely no chance without a stack trace. Either way, disabling and enabling the SJQ plugin should get the task queue running again. If not, restarting the Sage service will. I actually had this happen to me a month or two ago and it was the task queue thread that crashed. Unfortunately, I couldn't get a stack trace because I don't properly catch it from that thread and log it so the JVM just eats it when the thread dies. It's likely the same for you, so all you can do is just restart the plugin or SageTV. It doesn't happen anywhere near frequent enough for me to fix the code to properly log it (esp. given this plugin has long since been EOL'd). But maybe it's a different bug that has a stack trace, so still worth a look. At this point, the bug would have to crash the thread so frequently that it drives me bonkers for me to fix it. One crash, 2 or 3 months ago -- the first and only I've ever encountered -- isn't going to warrant a fix. A stack trace showing an obvious bug with a quick fix... yeah, probably something I'd do some Sunday morning while the temperatures remain -37C with the windchill in these parts.

[ptaylor]

Couldn't find a sagetv_0.txt file, and the only thing showing up in the sjq.log file is a bunch of these... They happen sometimes every 30 seconds or so, other times there is an hour or longer gap between them. SJQ is just running on my SageTV server and the client plug-in is the only client.

PHP Code:

2014-01-02 21:34:51,376 ERROR [Handler]: IOError: 192.168.111.51:63284
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) 


[Slugger]

Those are expected. So it's probably the same thing I saw a couple months back. The thread is dying and the exception is not being logged properly by my code. Nothing for us to do unless you notice it happening a lot and/or can describe a way to quickly & easily reproduce the problem.

[ptaylor]

I also did get an "Out of Memory Detected" system message in SageTV that I just noticed. It was right around the time that the copy job failed. Not that I think that can help you figure out that issue, but if it isn't a frequent occurrence, I'm not terribly concerned either.

I've disabled CommercialDetector and moved that function to SJQ. My copy jobs are defined as taking 100 resources, so there shouldn't be any chance that a commercial skip job (25 resources) will be running while it's trying to do the move...

I have my recordingStopped events running these tasks: COMSKIP;MOVETONAS

Am I right in assuming that the COMSKIP for a given recording should be added to the Queue before MOVETONAS for that same recording?

I'd rather it work in this fashion, since when MOVETONAS runs, it triggers a core media scan at the end, and I'm afraid that if it runs first, the file may not be known to SageTV by the time the COMSKIP task runs.

[Slugger]

Originally Posted by ptaylor

Am I right in assuming that the COMSKIP for a given recording should be added to the Queue before MOVETONAS for that same recording?

No, that assumption is not valid. It may end up working out that way, but it's definitely not guaranteed. If you want that kind of guarantee you will have to add a check to the pretest of the move task and send it back to the queue until you've determined that comskip has already run on the recording.

[ptaylor]

Ok, stole code from the com skip test and added this to my move test:

PHP Code:

// Code below looks to see if a .edl file exists (indicating Comskip has ran) before moving the file.
def path = new File(SJQ4_METADATA.get("SJQ4_PATH"))
def fileName = SJQ4_METADATA.get("SJQ4_LAST_SEGMENT")

def edl = fileName.substring(0, fileName.lastIndexOf('.')) + ".edl"
def edlFile = new File(path, edl)
if(!edlFile.exists()) {
   println "Comskip has not executed yet; returning task to queue!"
   return 1
} 


I'm not sure if the last if statement (with the !) is valid groovy or not, but I should know in within the next couple of hours, since I have a recording currently in progress.

[Slugger]

It's valid.

Do you comskip every recording? If not, then recordings that aren't comskippped are going to be returned to the queue in perpetuity.

[ptaylor]

Yep, I let it ComSkip everything right now. There are a few channels that don't have much in the way of commercials, but I don't have any of the major pay networks that are commercial free.

I imagine I could look at some metadata to determine if the recording was taken from one of several stations that are known to not have commercials, and if it matches one of those stations, I could create a 0 byte .edl file. (I'm assuming that the station is available in the metadata?)

That all involves me learning more Groovy than I feel like right now, though. I do enough programming during the week.

The good news is that since I added the code in my last post, I have had a recording where the Move task was kicked off before the ComSkip task, and it worked as expected! The Move task went back into the queue, and about 5 minutes later when ComSkip was complete, the Move task kicked off again and successfully moved the file to my NAS.

[Slugger]

Since moving to Phoenix 2 for my STV, I've lost all SJQ interaction from my tv. So now I have to do everything from the web and I'm learning the deficiencies of the SJQ web UI. As needed, I'm adding things in and will release the updates. I have my first update done and ready to release probably this weekend or next week -- whenever I get around to it.

This update adds the ability to attach media file metadata to a queued task from the web ui. Currently, you can queue a task from the web ui, but you can't attach metadata to it, which makes it useless for queuing up things like comskip tasks or any task that relies on metadata. So I've added that ability and will release it soon.

I post this now because if there's anything else that might be needed, you might be able to get it into this next update. Small(ish) things have the best chance and there's no promises. Anything that will take me more than a couple hours probably won't happen unless I think, "whoa, yeah, I could really use that myself."

You've got a couple of days to post your ideas/requests.

[wayner]

I don't think you will be surprised by this:

A JVM page that shows the JVM info shown on the monitor by tmiranda or in the Sage Info page with the ability to do a cleanup.

A page that gives you the option to do a restart of the SageTV service.

FYI - I had a similar problem when I switched from Diamond to Gemstone a month ago but I was able to add the SJQ menu back in with help from the guys who wrote Gemstone.

[Slugger]

Originally Posted by wayner

I don't think you will be surprised by this:

A JVM page that shows the JVM info shown on the monitor by tmiranda or in the Sage Info page with the ability to do a cleanup.

A page that gives you the option to do a restart of the SageTV service.

These are general webui requests, not SJQ webui requests.

As it turns out, I actually need to do a new webui release to update the groovy templates in support of my SJQ update so there's going to be a webui update before I release this.

This means there's a chance that one or both of those things might happen, but I haven't done a webui build since migrating the project back to SourceForge, which means I have to make all the build updates to support the move back to SF. And that really, really sucks in this case because it's probably 3-4 hours to mod and test the changes for the build and the changes I need to make to the groovy templates literally took me about 90 seconds and 75 seconds of that was googling the URL I needed to copy and paste into the template file.

Because of the extra webui release (and the dreadful overhead of setting up the build env for it), I'm not so sure about the new release happening this week or next. It's more of a when I get motivated to do the necessary migration work for the webui codebase (especially because I already have the sjq web mods running locally on my system). Anyway, when I do the webui update, I'll see about throwing these requests in.

[wayner]

Originally Posted by Slugger

These are general webui requests, not SJQ webui requests.

I kind of figured that if you have to make webui changes for SJQ then you may be open to making other changes as well.

[Slugger]

The SJQ web ui pages are a separate plugin and so SJQ specific changes don't require a full webui build/release to update. But as I said, I need to do a webui update anyway this one time to update the groovy templates in support of the SJQ changes so you've managed to get a little lucky this time.

However, as I think about it, the JVM status/garbage collector thing is probably doable and though the restart is doable (and actually easier to implement), I'm not so sure if I want to add it to the stock webui. Why? A simple click to restart the Sage service is dangerous. Even with a confirm dialog box, it's still a little too easy for mistakes to happen and I don't want to hear it when someone accidentally restarts their Sage service in the middle of the wife's recording of <insert favourite show here>. You've still got a few days (maybe more) to convince me otherwise on this one though.

[graywolf]

Originally Posted by wayner

I don't think you will be surprised by this:

A JVM page that shows the JVM info shown on the monitor by tmiranda or in the Sage Info page with the ability to do a cleanup.

+1 on the JVM Cleanup link/button

[wayner]

But thing of the other example - your wife calls when you are at work or out of town and complains about really slow performance of the UI. You pull out your smartphone and restart the service and tell her to try again in 3 minutes and that she can thank Slugger for that capability!

To be honest it may make more sense to incorporate this functionality into another web server (assuming that you have one on your LAN) since sometimes when the server gets bogged down it kills the web UI as well. Then you would run a batch file that contains something like "net stop SageTV && net start SageTV" and you are done, at least for a Windows server.

I do actually have a Groovy web page that can restart Sage but it requires manually entering the URL.

Actually I did remember seeing the SJQ webUI stuff - it is in Groovy, isn't it.

Regrading the JVM stuff - I am surprised that this wasn't part of the original web UI but maybe it is only an issue for people with lots of extenders, like me.