Plugin: Sage Job Queue (SJQ)

[Slugger]

Originally Posted by loki

SJQ - love this plugin to SageTV! Been using SJQ for the last two months, offloading comskip/transcoding from my underpowered sagetv server to desktop.

Also adding variables to custom commands would really be a nice additional feature,any plans for this?

# Sample Server Config 
# Run video convert on The Daily Show 
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "The Daily Show" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 9
HBCONVERT tv 2pass
} 

# Run video convert on The Colbert Show
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "The Colbert Show" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 8
HBCONVERT tv 1pass
} 

# Run video convert on Phineas and Ferb
if [IsTV == "true" && IsActivelyRecording == "false" && Title =^ "Phineas and Ferb" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.mp4"]
{
:PRIORITY 7
HBCONVERT cartoon
}

# Sample Clients Config
:MAPDIR "D:\\MyVideos" "\\\\pvr01\\Videos"

COMSKIP {
:CPU LOW
:MAX 2
"C:\\dvd\\tools\\comskip.bat" "%c%" 
}

HBCONVERT {
:CPU low
:MAX 1
# where %1 %2 .... would be options passed from the server to the client
"C:\\dvd\\tools\\hbconvert.bat" "%c%" "%1" "%2" 
}

Not a bad idea. This will take some work and heavy testing so I can promise you I won't even consider the idea until the fall, but I definitely see the benefit of this approach. Please open an issue ticket at the project site with the details of the feature request and we'll see what happens when the warm weather fades.

[personalt]

i have a backlog of about 20 shows in comkskip. I wanted to try offloading some comskip to my desktop. I installed the client and it connected fine. All my shows are in V:\Shows\ on the server. I mapped

V:\ on the desktop to the v:\ on the server so the paths are exactly the same.

I am running the same rules on the desktop however it clears out the whole list right away but comskip never runs. Of course I have comskip in the same folder on both machines.

is there something else special i need to do when running it on a remote machine?

//Client options
// TASK definition
COMSKIPMPEG {
:CPU NORMAL
:RETURNCODE 1
:MAX 1
"C:\\comskip\\comskip.exe \"%c%\""
}

COMSKIPH264 {
:CPU NORMAL
:MAX 1
:RETURNCODE 1
"C:\\comskip\\comskip.exe \"%c%\""
}

[Beefcake550]

From what I remember, you need not map the area, but you need Guest account turned on? I think SJQ uses the UNC path anyway and that's why the v: mapping doesn't matter and why you need guest account enabled (but don't turn on remote access).

Good luck...

[Slugger]

Originally Posted by personalt

i have a backlog of about 20 shows in comkskip. I wanted to try offloading some comskip to my desktop. I installed the client and it connected fine. All my shows are in V:\Shows\ on the server. I mapped

V:\ on the desktop to the v:\ on the server so the paths are exactly the same.

I am running the same rules on the desktop however it clears out the whole list right away but comskip never runs. Of course I have comskip in the same folder on both machines.

is there something else special i need to do when running it on a remote machine?

//Client options
// TASK definition
COMSKIPMPEG {
:CPU NORMAL
:RETURNCODE 1
:MAX 1
"C:\\comskip\\comskip.exe \"%c%\""
}

COMSKIPH264 {
:CPU NORMAL
:MAX 1
:RETURNCODE 1
"C:\\comskip\\comskip.exe \"%c%\""
}

What are the SJQ server logs saying? Are the tasks being marked as failed? Success? What are the task logs saying?

[personalt]

Originally Posted by Slugger

What are the SJQ server logs saying? Are the tasks being marked as failed? Success? What are the task logs saying?

I see nothing(no entries at all) in the client logs. I did a quick look but can you point me in the right direction as to where I need to go to enable client logging?

server logs shows nothing of value but can attached it when I get home.

what I find interesting is that I start with 20 shows in the active queue. When I enable the remote client the active queue drops to one(the file running on the sage server) bu the other shows do not appear in the completed log or the failed queue.

If I then disable the remote client by changing the name of the tasks that the remote client can process and re-run the queue loader the list of 20 shows appear again. To disable to the remote client I was just changing the task from MPEGCOMSKIP to MPEGCOMSKIPX to the remote client doesn't pick up any tasks.

[Slugger]

Originally Posted by personalt

I see nothing(no entries at all) in the client logs. I did a quick look but can you point me in the right direction as to where I need to go to enable client logging?

server logs shows nothing of value but can attached it when I get home.

what I find interesting is that I start with 20 shows in the active queue. When I enable the remote client the active queue drops to one(the file running on the sage server) bu the other shows do not appear in the completed log or the failed queue.

If I then disable the remote client by changing the name of the tasks that the remote client can process and re-run the queue loader the list of 20 shows appear again. To disable to the remote client I was just changing the task from MPEGCOMSKIP to MPEGCOMSKIPX to the remote client doesn't pick up any tasks.

Client logging is on by default; there's nothing to turn on or off. Debug logging on the server does need to be enabled (then disabled as soon as possible). Do that from the settings menu. However, I've found the code that does what you're describing and there's no logging in that code at the moment. However, the queue would only clear like that if the Sage API is telling SJQ that there are no physical files associated with the Sage MediaFile object you're trying to get SJQ to process.

To be sure that I'm looking at the right code, I've added some debug logging and will need you to:

* Upgrade the SJQ server to snapshot 488 (now available on Google Code)
* Enable debug logging in SJQ
* Reproduce this scenario
* Check SJQ server logs for statements like:

TaskQueue: Wanted to return MediaID xxx [AiringID = yyy], but didn't because SageAPI says MediaFile is null!

And report back your findings...

[personalt]

Crap.. Seems like I am going backwards instead of foward

I started with lots of the error right below this, then I then added a server restriction which fits my local and remote client. - 192.168.1.0/24;127.0.0.1/32
My client is 192.168.1.99, Sever is 192.168.1.100 but it appears on the loopback adapter in the client list.

2009/07/20 19:42:08.812 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:42:08.937 WARNING: All client connections are being accepted and processed, please consider setting up client restrictions in SJQ settings

After adding that restriction the first error went away. My new error log is below. I feel like I have some dumb typo but I cant see it. What is weird is when I just had the one client this is the config that I used and the server processed files fine .

There seems to be no issue in the rules as things enter the queue but I cant see any issues with the client side either.

if [IsTV == "true" && FileExists == "%d%\\%p%.mpg" && FileExists != "%d%\\%p%.edl" && IsActivelyRecording == "false" && IsScheduledRecording == "true"] {
:PRIORITY 100
COMSKIPMPEG
}

// Comskip on H264
if [IsTV == "true" && FileExists == "%d%\\%p%.ts" && FileExists != "%d%\\%p%.edl" && IsActivelyRecording == "false" && IsScheduledRecording == "true"] {
:PRIORITY 100
COMSKIPH264

}

---------------------------------
Same setup on both clients.
:MAXPROCS 1
// TASK definition
COMSKIPMPEG {
:CPU LOW
:RETURNCODE 1
:MAX 1
"C:\\comskip\\comskip.exe \"%c%\""
}

COMSKIPH264 {
:CPU LOW
:MAX 1
:RETURNCODE 1
"C:\\comskip\\comskip.exe \"%c%\""
}

-------------------------------------
2009/07/20 19:48:56.062 QueueLoader awakened: sleep interrupted
2009/07/20 19:48:56.218 Using MediaMask: 'VT'
2009/07/20 19:48:56.500 LogCleaner instance started
2009/07/20 19:48:56.531 FileCleaner instance started
2009/07/20 19:48:56.796 FileCleaner instance finished [265ms]
2009/07/20 19:48:56.812 LogCleaner instance finished [297ms]
2009/07/20 19:51:40.984 QueueLoader awakened: sleep interrupted
2009/07/20 19:51:41.078 Using MediaMask: 'VT'
2009/07/20 19:51:41.078 Skipping: COMSKIPMPEG::18751::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.078 Skipping: COMSKIPMPEG::18755::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18763::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18767::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18771::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18779::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18783::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18787::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.093 Skipping: COMSKIPMPEG::18791::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18855::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18859::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18875::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18879::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18883::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.109 Skipping: COMSKIPMPEG::18887::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18931::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18935::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18939::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18943::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18947::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18955::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.125 Skipping: COMSKIPH264::18959::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.156 Skipping: COMSKIPH264::844069::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.171 Skipping: COMSKIPH264::844070::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.171 Skipping: COMSKIPH264::844071::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.171 Skipping: COMSKIPH264::851393::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.171 Skipping: COMSKIPH264::851457::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.171 Skipping: COMSKIPH264::851496::100::CREATED, already in queue or task currently running
2009/07/20 19:51:41.375 LogCleaner instance started
2009/07/20 19:51:41.390 FileCleaner instance started
2009/07/20 19:51:41.671 FileCleaner instance finished [281ms]
2009/07/20 19:51:41.687 LogCleaner instance finished [297ms]
2009/07/20 19:52:09.531 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:10.484 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:10.609 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:11.218 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:11.640 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:12.437 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:12.984 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:13.578 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:17.734 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:17.843 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:18.375 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:19.203 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:19.328 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:21.234 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:21.343 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:22.062 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:22.187 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:23.531 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:23.640 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!
2009/07/20 19:52:24.531 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!


Go BackClear Log

[Slugger]

Did you upgrade to 488? Is that output from 488?

[personalt]

yes... but after letting it run a while longer I got this
2009/07/20 20:36:14.046 TaskQueue: Wanted to return MediaID 18887 [AiringID = 389787], but didn't because SageAPI says MediaFile is null!
2009/07/20 20:36:14.046 TaskQueue: Wanted to return MediaID 18883 [AiringID = 389830], but didn't because SageAPI says MediaFile is null!
2009/07/20 20:36:14.046 TaskQueue: Wanted to return MediaID 18879 [AiringID = 389843], but didn't because SageAPI says MediaFile is null!
On the client I mapped the v: to \\sageserver\DriveWithShows

so v:\ on the client gives me one folder called shows the same as the v: on the server.

Is that okay? or should I go back and use the map dir?

[Slugger]

Ok, so now I know why the queue is emptying out - those media objects are matching your rules, but according to SageAPI, there are no physical files on the hard drive for the media object so when SJQ gets that info from SageAPI it just silently dumps the task from the queue.

What you need to do now is go to the media debugger in SJQ and enter one of those media file ids that the logs are saying is returning null and enter that number and run the debugger against that media object, go to the logs and paste in the debug output (please add code tags around it for easier reading).

[personalt]

I am thinking it cant find the files on the server when I mapped the v:\ on the client so I am trying to set up MAPDIR and use shares. But I cant not seem to get the syntax right

On my server called cube I have V drive. On the V drive I have a folder called Shows were all the sage recordings go. All my shows that are recorded end up there so in the sage information for the file locations is in this format.

V:\Shows\house_1234.ts

I added the MAPDIR entry below to the remote client and on the server I shared v:\Shows as ShowsShare.. But no luck.

----

:MAPDIR "V:\\Shows" "\\\\cube\\ShowsShare"

:MAXPROCS 1
// TASK definition
COMSKIPMPEG {
:CPU LOW
:RETURNCODE 1
:MAX 1
"C:\\comskip\\comskip.exe \"%c%\""
}

COMSKIPH264 {
:CPU LOW
:MAX 1
:RETURNCODE 1
"C:\\comskip\\comskip.exe \"%c%\""
}


I get the feeling it is not finding the file again but I dont get that error about the missing media but it does blow throw the queue right away. If I time it right I do see shows with the client ip address in the active task. It is like it is running the task at lighting speed as when I reload the active queue only has the one task running on the server.

[personalt]

I was posting this while you were typing your last response.. Will try that and get back in a few..

[personalt]

Those three entries in the log come back to no files.. However here is a entry that I saw in the queue and then feed throught the debugger

2009/07/20 21:09:23.875	Processing 'Planet Earth'...
2009/07/20 21:09:23.875		Line 1: Evaluating 'IsTV == "true"' == true
2009/07/20 21:09:23.875		MediaVar '%s%' == 'Mountains'
2009/07/20 21:09:23.875		MediaVar '%y%' == ''
2009/07/20 21:09:23.875		MediaVar '%c%' == 'V:\Shows\PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%d%' == 'V:\Shows'
2009/07/20 21:09:23.875		MediaVar '%f%' == 'PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%e%' == 'ts'
2009/07/20 21:09:23.875		MediaVar '%p%' == 'PlanetEarth-Mountains-2025088-0'
2009/07/20 21:09:23.875		MediaVar '%t%' == 'Planet Earth'
2009/07/20 21:09:23.875		Expanded '%d%\%p%.mpg' to 'V:\Shows\PlanetEarth-Mountains-2025088-0.mpg'
2009/07/20 21:09:23.875		Line 1: Evaluating 'FileExists == "%d%\%p%.mpg"' == false
2009/07/20 21:09:23.875		MediaVar '%s%' == 'Mountains'
2009/07/20 21:09:23.875		MediaVar '%y%' == ''
2009/07/20 21:09:23.875		MediaVar '%c%' == 'V:\Shows\PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%d%' == 'V:\Shows'
2009/07/20 21:09:23.875		MediaVar '%f%' == 'PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%e%' == 'ts'
2009/07/20 21:09:23.875		MediaVar '%p%' == 'PlanetEarth-Mountains-2025088-0'
2009/07/20 21:09:23.875		MediaVar '%t%' == 'Planet Earth'
2009/07/20 21:09:23.875		Expanded '%d%\%p%.edl' to 'V:\Shows\PlanetEarth-Mountains-2025088-0.edl'
2009/07/20 21:09:23.875		Line 1: Evaluating 'FileExists != "%d%\%p%.edl"' == true
2009/07/20 21:09:23.875		Line 1: Evaluating 'IsActivelyRecording == "false"' == true
2009/07/20 21:09:23.875		Line 1: Evaluating 'IsScheduledRecording == "true"' == true
2009/07/20 21:09:23.875		Line 7: Evaluating 'IsTV == "true"' == true
2009/07/20 21:09:23.875		MediaVar '%s%' == 'Mountains'
2009/07/20 21:09:23.875		MediaVar '%y%' == ''
2009/07/20 21:09:23.875		MediaVar '%c%' == 'V:\Shows\PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%d%' == 'V:\Shows'
2009/07/20 21:09:23.875		MediaVar '%f%' == 'PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%e%' == 'ts'
2009/07/20 21:09:23.875		MediaVar '%p%' == 'PlanetEarth-Mountains-2025088-0'
2009/07/20 21:09:23.875		MediaVar '%t%' == 'Planet Earth'
2009/07/20 21:09:23.875		Expanded '%d%\%p%.ts' to 'V:\Shows\PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		Line 7: Evaluating 'FileExists == "%d%\%p%.ts"' == true
2009/07/20 21:09:23.875		MediaVar '%s%' == 'Mountains'
2009/07/20 21:09:23.875		MediaVar '%y%' == ''
2009/07/20 21:09:23.875		MediaVar '%c%' == 'V:\Shows\PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%d%' == 'V:\Shows'
2009/07/20 21:09:23.875		MediaVar '%f%' == 'PlanetEarth-Mountains-2025088-0.ts'
2009/07/20 21:09:23.875		MediaVar '%e%' == 'ts'
2009/07/20 21:09:23.875		MediaVar '%p%' == 'PlanetEarth-Mountains-2025088-0'
2009/07/20 21:09:23.875		MediaVar '%t%' == 'Planet Earth'
2009/07/20 21:09:23.875		Expanded '%d%\%p%.edl' to 'V:\Shows\PlanetEarth-Mountains-2025088-0.edl'
2009/07/20 21:09:23.875		Line 7: Evaluating 'FileExists != "%d%\%p%.edl"' == true
2009/07/20 21:09:23.875		Line 7: Evaluating 'IsActivelyRecording == "false"' == true
2009/07/20 21:09:23.875		Line 7: Evaluating 'IsScheduledRecording == "true"' == true

[Slugger]

And this task is one that was queued then wiped out? If so, are you sure it didn't end up in the failed or completed task list? If not, then I'm confused as to why it didn't.

[personalt]

yes... this was one that was wiped out. it does not show up in failed or completed. I do agree with you totally, I would expect this to show up in either one of them depending if the return code came back as expected. But it isnt showing up in either(failed or completed). If I disable the remote client the queue just shows the one task being worked on via the server. If I enable it it blows through the list in a few seconds.

The only thing I see often in the log now is
2009/07/20 22:05:49.703 getPopCandidates(): 192.168.1.99 is running MAXPROCS processes already!

If I wanted to hardcode this read from \\cube\ShowsShare and use the %f value how would I do that? I know that I need to escape some characters but that is not something I am strong in.
This is what I run now.

"C:\\comskip\\comskip.exe \"%c%\""

[nyplayer]

personalt,

Are you sure that you have on your client a folder c:\comskip with comskip.exe in it. Comskip in order to run in a client it must also exist there. If it cannot find comskip in your client the jobs will just go poof.

[personalt]

Yes... And from the command line I have run

c:\comskip\comskip.exe \\cube\ShowsShare\theshow.mpg

and it runs fine...

I think my nextstep is to understand how to rewrite that with the %f variable. If I had more then one share I would want to make sure I could use the mapdir but for now since I only have one share I just want to hardcode the \\cube\ShowsShare\ and use the %f variable.

I just dont know how to escape this if I convert it to use a share.
"C:\\comskip\\comskip.exe \"%c%\""

[nyplayer]

Can't you just create a comskip.bat file and run that with the %f

ex:

cd c:\comskip
c:
start /b /w /low comskip.exe "\\cube\ShowsShare\%1"

"C:\\comskip\\comskip.bat %f"

[Slugger]

Originally Posted by nyplayer

personalt,

Are you sure that you have on your client a folder c:\comskip with comskip.exe in it. Comskip in order to run in a client it must also exist there. If it cannot find comskip in your client the jobs will just go poof.

Is this reproducible? If so, that's a bug that should be fixed and it seems like it'd be the cause of personalt's problems (but that also means SJQ isn't finding comskip on the remote client machine).

[personalt]

I tried this nyplayers suggestion. I set up comskip.bat. Before calling the batch file from Sage I ran it from the command prompt as a test.

I ran -> c:\comskip\comskip.bat BrotherSister-231231.mpg

comskip started fine, it found the brothers and sisters file on the share \\cube\\ShowsShares

However this code below doesnt do the same thing as c:\comskip\comskip.bat BrotherSister-231231.mpg

Do I need to escape the %f somehow?

COMSKIPH264 {
:CPU LOW
:MAX 1
:RETURNCODE 1
"C:\\comskip\\comskip.bat %f"
}

Originally Posted by nyplayer

Can't you just create a comskip.bat file and run that with the %f

ex:

cd c:\comskip
c:
start /b /w /low comskip.exe "\\cube\ShowsShare\%1"

"C:\\comskip\\comskip.bat %f"