Odd problem with Network Encoder

[panteragstk]

I'm not sure what exactly is happening, but I'll do my best to explain.

I use the sage v9 docker and also a sage v7 installed on a windows 2012 VM to host my colossus cards as network tuners.

Everything works, but there has been some strange behavior recently.

First, I've tested gentuner and it is able to tune without issue on all three colossus cards, but for some reason the channel will change in the middle of a recording for something that should be recording on another tuner. I check the other tuner and the recording is fine. Huh? It's almost as if the channel is getting changed on two boxes at once. That makes no sense, but it's happening. I've tested repeatedly and can't figure out what could be causing the issue.

Second, at the end of a show I get "colossus stopped producing data" errors if I'm watching live TV. Happens every time. Nothing has changed in my setup so I'm not sure where to start. If I try to play the show that should be recording still I get filesystem access errors even though nothing is technically wrong. After about a minute it returns to normal.

This was especially annoying tonight during the Oscars since it went almost an hour over there were three different instances where the recording got interrupted for the above issue. The random channel changing issue also happened at around 9pm cst IIRC.

I've linked all the logs so hopefully it is something simple that I can fix.

Thanks for the help.

Logs

[Fuzzy]

What channel did the oscars recording change to? the only thing that really happened at 9pm is the start of Bar Rescue (ch 241) on colossus 2, while the oscars were being recorded on colossus 1. Hard to look further into this without seeing your gentuner scripts as well, to see why the tuning for colossus 2 might be affecting colossus 1's stb.

[panteragstk]

Originally Posted by Fuzzy

What channel did the oscars recording change to? the only thing that really happened at 9pm is the start of Bar Rescue (ch 241) on colossus 2, while the oscars were being recorded on colossus 1. Hard to look further into this without seeing your gentuner scripts as well, to see why the tuning for colossus 2 might be affecting colossus 1's stb.

Bar rescue was it.

I uploaded the gentuner script and my properties file. I still have the ip control enabled on the host server. That wouldn't cause this to occur would it? It's almost as if sage doesn't realize that the tuner is in use.

Also, just confirmed that this is not an issue on the host server. It is able to transition from show to show without delay.

[Fuzzy]

Originally Posted by panteragstk

Bar rescue was it.

I uploaded the gentuner script and my properties file. I still have the ip control enabled on the host server. That wouldn't cause this to occur would it? It's almost as if sage doesn't realize that the tuner is in use.

Also, just confirmed that this is not an issue on the host server. It is able to transition from show to show without delay.

So this is a network encoder in windows, but you are tuning it from the main server in the unRAID docker? Do you also by chance have the gentuner.log from that time period as well? That should show what gentuner was told to do. As far as I can tell, you have the following configs:

Hauppauge Colossus Capture 0 is tuning DirecTV-Tuner-1 @ 192.168.1.76
Hauppauge Colossus Capture 1 is tuning DirecTV-Tuner-2 @ 192.168.1.77
Hauppauge Colossus Capture 2 is tuning DirecTV-Tuner-3 @ 192.168.1.78

gentuner.log should reflect this behavior.

[panteragstk]

I've attached the log as requested.

I will say I looked at the properties file and saw some duplicate entries under device name. Some had multiple gentuner device names as well as old IP addresses that I used when the windows server was the primary. I edited the entries to reflect what should be correct. We'll see if that helps.

I also want to add that the tuning issue is odd and random, but the main issue I'm having is transitioning from show to show. It pretty much stops recording for around a minute and the log reflects a lot of activity. Insight into that would be very helpful since right now live tv is pretty much not working.

[Fuzzy]

Originally Posted by panteragstk

I've attached the log as requested.

I will say I looked at the properties file and saw some duplicate entries under device name. Some had multiple gentuner device names as well as old IP addresses that I used when the windows server was the primary. I edited the entries to reflect what should be correct. We'll see if that helps.

I also want to add that the tuning issue is odd and random, but the main issue I'm having is transitioning from show to show. It pretty much stops recording for around a minute and the log reflects a lot of activity. Insight into that would be very helpful since right now live tv is pretty much not working.

That log entry looks fine. On the 26th, at 21:00, the gentuner script was told to change DirecTV-Tuner-3 to channel 241, which should have only affected the STB connected to Hauppauge Colossus Capture 2. It should have had no impact on the STB that was tuned to the Oscars on Hauppauge Colossus Capture 1.

That said, I am only seeing entries in the logfile from the actual gentuner binary, NOT from the perl script (which should also be writing entries, since $debug is set to 1). So It would appear that either the gentuner script cannot write to the logfile (permissions issue maybe), or the script you posted isn't what is actually being run.

[panteragstk]

How would I tell what is being run if it isn't the one I posted?

Also, what about the issue with live TV? Have you seen that before? It's a new one for me and I'm not sure what else to do with it.

[Narflex]

I took a look at the logs and the thing that stood out at me was the excessive amount of network errors talking to the network encoder like:

Sun 2/26 21:00:26.279 [FSManager@12b56219] Error communicating with encoding server:java.lang.NumberFormatException: For input string: "ERROR java.net.SocketTimeoutException: Read timed out"

It'd be useful to also see the log file from the network encoder as well. So if you post that log along with the log from your main server and then give a specific account of what happened at exactly what time...then it would make it easier to try to figure out what exactly was going on. Nothing else looked odd around 9pm in that log file.

[panteragstk]

Didn't see that one. Here is the log. It looks like there is an error with the encoding server.

This is an old install, my best bet to just start over again? Or is there something I can do that is less drastic? This server's job is only to host the colossus cards.

[Narflex]

OK, now I've found something very odd in the encoding server log where when it switches to a new file...it's doing the switch, then a stop and start...which isn't right. I'm not sure why, but with more logging we should be able to tell.

Set this in the Sage.properties on your main server and the encoding server:

network_encoder_debug=true

Then reproduce the problem where you get the error about accessing the file system, then I'll take another look and can hopefully shed some light on the issue.

What version of SageTV are you using on the encoding server?

[panteragstk]

Originally Posted by Narflex

OK, now I've found something very odd in the encoding server log where when it switches to a new file...it's doing the switch, then a stop and start...which isn't right. I'm not sure why, but with more logging we should be able to tell.

Set this in the Sage.properties on your main server and the encoding server:

network_encoder_debug=true

Then reproduce the problem where you get the error about accessing the file system, then I'll take another look and can hopefully shed some light on the issue.

What version of SageTV are you using on the encoding server?

I'm running 7.1.9. Nothing has changed on it since I moved to the v9 docker. Very strange.

The other odd thing is that if I watch using the 7.1.9 server the issue doesn't happen at all.

[panteragstk]

This seems like an issue.

WIN32 FAILURE HR=0x8007001f FILE=.\Encoder.cpp LINE=886

Full log attached.

[Narflex]

That error you pointed out isn't really a problem, I've seen that with the Colossus card usually.

For the logs, I want the log from both the main server and the encoding server. Also, let me know what time the problem happened at where you get the filesystem error. That error doesn't show up in the encoding server logs...and it looks like that's what you posted, and I didn't see anything abnormal in the log you just uploaded (nothing like I saw last time when the problem occurred in the main log).

[panteragstk]

Look at 3/1 at 14:16 and 14:40

I've included the main and encoding server logs here.

The error I get every time is "The device input "Hauppauge Colossus Capture 1 on 192.168.1.42:6969 componenet+spdif" stopped producing data while recording"

[Narflex]

OK, now I definitely see something odd...unfortunately it doesn't appear you set network_encoder_debug=true for the main server...so there's some logging that I'd like to see that's not in there.

What's happening is that when the server switches the encoding to the new file, and then queries for the size of that new file...it's getting the size of the old file sent back instead...so it thinks there's data in the new file when there isn't, and it also thinks the new file isn't growing in size...which is why it says it stopped producing data.

For example, it switches from Octonauts to DocMcStuffins at 14:15, and we see this right before the switch:

Wed 3/1 14:14:42.474 [Seeker@73c5107c] RootFile=/ fstype=0x9123683e fileLength=477879456 file=/var/recorded_tv_1/Octonauts-TheOctonautsandTheUnderseaStormTheOctonautsandTheGiantSquid-23381316-0.mpg

then right after the switch:

Wed 3/1 14:15:00.137 [Seeker@73c5107c] RootFile=/ fstype=0x9123683e fileLength=496267736 file=/var/recorded_tv_1/DocMcStuffins-S03E31-StPatricksDayDilemmaaGiantSave-23381327-0.mpg

The file length should not be 496MB right after recording starts...I *know* I've seen this before, and if you weren't on 7.1.9 already for your network encoder, I'd suggest upgrading it.

So can you get me new logs with network_encoder_debug=true set on the main server as well? Also, do you know how to build your own Sage.jar and write basic Java code? (because this problem is so odd, it may require adding debug code into SageTV to figure it out)

[wnjj]

Hi Jeff.

There might be something here in the the GET_FILE_SIZE handler in EncondingServer worth looking at:

            else if (str.startsWith("GET_FILE_SIZE "))
            {
              String filename = str.substring("GET_FILE_SIZE ".length());
              // Find the device performing this capture
              java.util.Iterator walker = captureMap.entrySet().iterator();
              while (walker.hasNext())
              {
                java.util.Map.Entry ent = (java.util.Map.Entry) walker.next();
                if (ent.getValue() != null && ent.getValue().equals(filename))
                {
                  capDevInput = (CaptureDeviceInput) ent.getKey();
                  capDev = capDevInput.getCaptureDevice();
                  currRecordFile = ent.getValue().toString();
                  break;
                }
              }
              if (filename.equals(currRecordFile))
                outStream.write((((capDev != null) ? capDev.getRecordedBytes() : 0) + "\r\n").getBytes(Sage.BYTE_CHARSET));
              else
                outStream.write((new java.io.File(filename).length() + "\r\n").getBytes(Sage.BYTE_CHARSET));
            }

I don't know how or when the the capture map gets updated but I do see that in the above code block if the 'new' file isn't found in the map it will return an incorrect value.

The existing 'currRecordFile' variable doesn't get cleared before searching the capture map (while loop) so the function will simply return the previous file's size. 'currRecordFile' should probably be cleared before the 'while' loop to force the system to fetch the file size using the io.File.length() method if it's not yet in the capture map.


EDIT: 'currRecordFile' actually gets set to the new file in the 'SWITCH' handler so if the capture map doesn't have the new file yet, this code returns the previous capDev's recorded bytes.

On further exploration, it seems the capture map gets updated during the 'SWITCH' code too so scratch this idea. Maybe the capDev's internal recorded bytes value isn't being reset after the switchover?

[panteragstk]

Originally Posted by Narflex

OK, now I definitely see something odd...unfortunately it doesn't appear you set network_encoder_debug=true for the main server...so there's some logging that I'd like to see that's not in there.

What's happening is that when the server switches the encoding to the new file, and then queries for the size of that new file...it's getting the size of the old file sent back instead...so it thinks there's data in the new file when there isn't, and it also thinks the new file isn't growing in size...which is why it says it stopped producing data.

For example, it switches from Octonauts to DocMcStuffins at 14:15, and we see this right before the switch:

Wed 3/1 14:14:42.474 [Seeker@73c5107c] RootFile=/ fstype=0x9123683e fileLength=477879456 file=/var/recorded_tv_1/Octonauts-TheOctonautsandTheUnderseaStormTheOctonautsandTheGiantSquid-23381316-0.mpg

then right after the switch:

Wed 3/1 14:15:00.137 [Seeker@73c5107c] RootFile=/ fstype=0x9123683e fileLength=496267736 file=/var/recorded_tv_1/DocMcStuffins-S03E31-StPatricksDayDilemmaaGiantSave-23381327-0.mpg

The file length should not be 496MB right after recording starts...I *know* I've seen this before, and if you weren't on 7.1.9 already for your network encoder, I'd suggest upgrading it.

So can you get me new logs with network_encoder_debug=true set on the main server as well? Also, do you know how to build your own Sage.jar and write basic Java code? (because this problem is so odd, it may require adding debug code into SageTV to figure it out)

I've got the property set now. Sorry, I misunderstood and thought you wanted it set on the encoding server. It's set on both now.

As far as coding goes, I'm very much a newbie, but maybe my brother can help. He is very well versed in Java. It is very odd that this problem suddenly appeared when everything was working perfectly. I usually get the hard to solve issues though...Brings back early v7 memories.

Do you think scrapping the encoding server and upgrading to sage v9 would help? It's only job is hosting network encoders so it would be trivial to do that.

Here are the logs. Look at 18:15 from 3/2/2017

[Narflex]

The new logs don't tell me a little more. Apparently the size of the old recording isn't increasing (so it's not still writing to that file)...AND the new recording doesn't get past zero bytes. It's almost like there's some other failure in the network encoder that isn't getting logged.

It's not a bad idea to try upgrading your network encoder to V9 and seeing what happens then. Just make a backup copy of the folder first so you can revert in case anything goes wrong.

[wnjj]

Originally Posted by Narflex

The new logs don't tell me a little more. Apparently the size of the old recording isn't increasing (so it's not still writing to that file)...AND the new recording doesn't get past zero bytes. It's almost like there's some other failure in the network encoder that isn't getting logged.

It's not a bad idea to try upgrading your network encoder to V9 and seeing what happens then. Just make a backup copy of the folder first so you can revert in case anything goes wrong.

What's odd to me is after the SWITCH, the old file should no longer be in the captureMap since the new show overwrites it. That means the GET_FILE_SIZE handler should return the actual file size using java.file.IO.Length when queried about the old file. What I see in the log is the final call for file size of the original file from the MediaServer returns a response of '0', followed by a call from Seeker for the new one which returns a number much like the old file's size.

It still looks like the capture device to current file mapping is off somehow, perhaps because MediaServer asked about the old file after the switch to the new file happened. It's like that call caused some internal variables to switch the current file back to the old one. There are several layers of file size handling code in Java plus a call into the native code. Some debug printing at all of those levels would sure help.

[panteragstk]

I upgraded my encoding server to v9. No change.

I totally removed sagetv from the encoding server and installed v9. No change.

I added a second sagetv docker on my unraid server with a new appdata folder. No change.

Tried installing the server on my win 10 machine, but it didn't find any network encoders. Odd. Didn't have time to dig into why.