OpenDCT: An open source digital cable tuner. - Page 33

Greg2dot0 · #**641** 03-24-2016, 10:07 AM

Quote:

Originally Posted by EnterNoEscape

Have you noticed if it's just a particular channel and time? If you would like to switch to the raw consumer and capture the same problematic recording at the same time and just send me the whole recording I can probably get a better idea of what's really going on. Otherwise I can send you a very verbose copy of OpenDCT and you can send me the huge log files, but the video would be preferred since then I can manipulate things without you needing to keep testing.

Also, the log rotates at mid-night, when it reaches 20MB or when OpenDCT is restarted, so I didn't see anything of interest. Can you get me the logs under archive with recording date on them?

I've purposefully tried to be random and differing on what times & channels I record on. This morning's recordings, it happened 3 times within an hour on 2 different tuners. I'll go ahead and set up the raw consumer and try to keep an eye on the logs and will stop the recording after I've captured the event to minimize the file size.

The log files are also too big to attach, so I'll shoot you a URL in a PM.

Greg2dot0 · #**642** 03-24-2016, 10:49 AM

Just one question, are you expecting that with the RAW consumer that I would see the issues in the logs that I saw with the other consumers (in some form or fashion), or would you just expect it to sit quietly and not complain even if there are issues in the stream?

EnterNoEscape · #**643** 03-24-2016, 12:31 PM

Quote:

Originally Posted by Greg2dot0

Just one question, are you expecting that with the RAW consumer that I would see the issues in the logs that I saw with the other consumers (in some form or fashion), or would you just expect it to sit quietly and not complain even if there are issues in the stream?

The raw consumer will not report the errors since it will just write the file as it was received which gives me the best chance of figuring out what's going on. Working with a file that's already potentially mangled or missing the problem frames isn't going to tell me nearly as much. That's partly why I was hoping you had an idea of when it might happen.

Greg2dot0 · #**644** 03-24-2016, 02:16 PM

Ok, I found a recording that seems to exhibit some of the playback issues of a mangled file. I wish there was a way to identify the timestamp of the point where the issues start. Would ffprobe offer up anything that I could use to isolate the problem?

Here's the link to the file (7.4gb):

https://onedrive.live.com/redir?resi...int=video%2cts

EnterNoEscape · #**645** 03-24-2016, 02:50 PM

Quote:

Originally Posted by Greg2dot0

Ok, I found a recording that seems to exhibit some of the playback issues of a mangled file. I wish there was a way to identify the timestamp of the point where the issues start. Would ffprobe offer up anything that I could use to isolate the problem?

Here's the link to the file (7.4gb):

https://onedrive.live.com/redir?resi...int=video%2cts

Thanks!

I'm not sure if it will come up because I don't think ffprobe will scan the entire file unless you tell it to. You could just try remuxing with ffmpeg and see what happens. I started a few very long recordings myself hoping to run into the issue, but so far I haven't had any luck.

The following command would have you just remuxing the first video and audio stream FFmpeg likes in most cases.

Code:

ffmpeg -i "input_file.ts" -c:v copy -c:a copy "output_file.ts"

I have a test that allows me to run any file through any consumer as if it was recording, that will allow me to fiddle with the content to see what strategy works best. I have a few ideas on how to handle this problem.

You probably won't want to leave that one up for long. I'd hate to see you get a warning from Microsoft about copyrighted content. I get paranoid about these things even though the intention is far from piracy.

EnterNoEscape · #**646** 03-24-2016, 03:54 PM

I can confirm it has a small problem at ~35 minutes (MCU commercial) and bigger one at ~56 minutes (end of a Coke commercial). I think I know what needs to be done.

matt91 · #**647** 03-24-2016, 06:24 PM

An issue just occurred for me tonight, but I think i know what happened (however, it'd be nice if someone can corroborate it so I don't have to worry anymore :-)

As I mentioned in an earlier post, I'm running a new install of Sage. As part of that, I hadn't really gone through my channel list and deactivate channels that I don't actually subscribe to. Therefore, Sage of course thinks it can record favorites from these channels.

I noticed last night and again tonight that the nightly news didn't start recording until 8 minutes after the hour. Other shows later on did record properly. In looking at the log, i think that Sage was feverishly trying to get a lock channels that I can't receive.

Here is part of the log showing last night and tonight from just before 1900 to 1908 when the recording actually starts. I also had a couple of shows that did record correctly shown.

I have now disabled these channels, but hopefully this isn't just a red herring of something else going on. thanks!

Code:





INFO   | jvm 1    | 2016/03/23 18:58:43.779 | 18:58:43.706 [SageTVRequestHandler-1283:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '113' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BuyingAlaska-AlaskanBeachTown-27736438-23.ts'...
INFO   | jvm 1    | 2016/03/23 18:59:53.633 | 18:59:53.600 [SageTVRequestHandler-1321:DCT-HDHomeRun Prime Tuner 131C22D1-1] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-1' to the file '/var/media/tv/RehabAddict-AllAboutFamily-27737488-24.ts'...
INFO   | jvm 1    | 2016/03/23 18:59:58.736 | 18:59:58.661 [SageTVRequestHandler-1322:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '113' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BuyingAlaska-AlaskanBeachTown-27736438-24.ts'...
INFO   | jvm 1    | 2016/03/23 19:00:03.839 | 19:00:03.775 [SageTVRequestHandler-1320:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  FFmpegSageTVConsumerImpl - SWITCH to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' was requested.
INFO   | jvm 1    | 2016/03/23 19:00:04.039 | 19:00:03.943 [SageTVRequestHandler-1322:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-0.ts'...
INFO   | jvm 1    | 2016/03/23 19:01:23.595 | 19:01:23.570 [SageTVRequestHandler-1371:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-1.ts'...
INFO   | jvm 1    | 2016/03/23 19:02:38.641 | 19:02:38.627 [SageTVRequestHandler-1404:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-2.ts'...
INFO   | jvm 1    | 2016/03/23 19:03:53.689 | 19:03:53.622 [SageTVRequestHandler-1424:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-3.ts'...
INFO   | jvm 1    | 2016/03/23 19:05:08.643 | 19:05:08.588 [SageTVRequestHandler-1443:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-4.ts'...
INFO   | jvm 1    | 2016/03/23 19:06:23.684 | 19:06:23.601 [SageTVRequestHandler-1467:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-5.ts'...
INFO   | jvm 1    | 2016/03/23 19:07:13.543 | 19:07:13.448 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:14.043 | 19:07:13.949 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:14.544 | 19:07:14.449 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:15.045 | 19:07:14.950 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:22.394 | 19:08:22.296 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:22.894 | 19:08:22.797 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:23.395 | 19:08:23.297 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:23.695 | 19:08:23.650 [SageTVRequestHandler-1503:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-2' to the file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-1.ts'...
INFO   | jvm 1    | 2016/03/23 19:08:24.896 | Output #0, mpegts, to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-1.ts':
INFO   | jvm 1    | 2016/03/23 19:08:53.715 | 19:08:53.615 [SageTVRequestHandler-1504:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-7.ts'...
INFO   | jvm 1    | 2016/03/23 19:10:08.661 | 19:10:08.609 [SageTVRequestHandler-1540:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-8.ts'...
INFO   | jvm 1    | 2016/03/23 19:11:23.706 | 19:11:23.620 [SageTVRequestHandler-1570:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-9.ts'...




INFO   | jvm 1    | 2016/03/24 18:55:10.277 | 18:55:10.234 [SageTVRequestHandler-9823:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-42.ts'...
INFO   | jvm 1    | 2016/03/24 18:56:40.329 | 18:56:40.240 [SageTVRequestHandler-9823:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-43.ts'...
INFO   | jvm 1    | 2016/03/24 18:58:10.280 | 18:58:10.200 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-44.ts'...
INFO   | jvm 1    | 2016/03/24 18:59:40.233 | 18:59:40.196 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-45.ts'...
INFO   | jvm 1    | 2016/03/24 19:00:00.146 | 19:00:00.073 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts'...
INFO   | jvm 1    | 2016/03/24 19:00:01.547 | Output #0, mpegts, to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts':
INFO   | jvm 1    | 2016/03/24 19:07:11.917 | 19:07:11.823 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:12.418 | 19:07:12.324 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:12.918 | 19:07:12.824 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:13.419 | 19:07:13.324 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)




INFO   | jvm 1    | 2016/03/23 21:00:00.688 | 21:00:00.589 [SageTVRequestHandler-2642:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '807' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-2' to the file '/var/media/tv/ModernFamily-ExpressYourself-27763018-0.ts'...
INFO   | jvm 1    | 2016/03/23 21:00:01.789 | Output #0, mpegts, to '/var/media/tv/ModernFamily-ExpressYourself-27763018-0.ts':
INFO   | jvm 1    | 2016/03/23 21:00:02.791 | 21:00:02.753 [SageTVRequestHandler-2644:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '869' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BeringSeaGold-DiggingDeep-27769677-0.ts'...
INFO   | jvm 1    | 2016/03/23 21:00:04.793 | Output #0, mpegts, to '/var/media/tv/BeringSeaGold-DiggingDeep-27769677-0.ts':
INFO   | jvm 1    | 2016/03/23 22:00:00.095 | 22:00:00.015 [SageTVRequestHandler-3200:DCT-HDHomeRun Prime Tuner 131C22D1-1] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-1' to the file '/var/media/tv/ChicagoPD-KasualWithaK-27762980-0.ts'...
INFO   | jvm 1    | 2016/03/23 22:00:01.396 | Output #0, mpegts, to '/var/media/tv/ChicagoPD-KasualWithaK-27762980-0.ts':

EnterNoEscape · #**648** 03-24-2016, 06:52 PM

Quote:

Originally Posted by matt91

An issue just occurred for me tonight, but I think i know what happened (however, it'd be nice if someone can corroborate it so I don't have to worry anymore :-)

As I mentioned in an earlier post, I'm running a new install of Sage. As part of that, I hadn't really gone through my channel list and deactivate channels that I don't actually subscribe to. Therefore, Sage of course thinks it can record favorites from these channels.

I noticed last night and again tonight that the nightly news didn't start recording until 8 minutes after the hour. Other shows later on did record properly. In looking at the log, i think that Sage was feverishly trying to get a lock channels that I can't receive.

Here is part of the log showing last night and tonight from just before 1900 to 1908 when the recording actually starts. I also had a couple of shows that did record correctly shown.

I have now disabled these channels, but hopefully this isn't just a red herring of something else going on. thanks!

Code:





INFO   | jvm 1    | 2016/03/23 18:58:43.779 | 18:58:43.706 [SageTVRequestHandler-1283:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '113' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BuyingAlaska-AlaskanBeachTown-27736438-23.ts'...
INFO   | jvm 1    | 2016/03/23 18:59:53.633 | 18:59:53.600 [SageTVRequestHandler-1321:DCT-HDHomeRun Prime Tuner 131C22D1-1] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-1' to the file '/var/media/tv/RehabAddict-AllAboutFamily-27737488-24.ts'...
INFO   | jvm 1    | 2016/03/23 18:59:58.736 | 18:59:58.661 [SageTVRequestHandler-1322:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '113' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BuyingAlaska-AlaskanBeachTown-27736438-24.ts'...
INFO   | jvm 1    | 2016/03/23 19:00:03.839 | 19:00:03.775 [SageTVRequestHandler-1320:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  FFmpegSageTVConsumerImpl - SWITCH to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' was requested.
INFO   | jvm 1    | 2016/03/23 19:00:04.039 | 19:00:03.943 [SageTVRequestHandler-1322:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-0.ts'...
INFO   | jvm 1    | 2016/03/23 19:01:23.595 | 19:01:23.570 [SageTVRequestHandler-1371:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-1.ts'...
INFO   | jvm 1    | 2016/03/23 19:02:38.641 | 19:02:38.627 [SageTVRequestHandler-1404:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-2.ts'...
INFO   | jvm 1    | 2016/03/23 19:03:53.689 | 19:03:53.622 [SageTVRequestHandler-1424:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-3.ts'...
INFO   | jvm 1    | 2016/03/23 19:05:08.643 | 19:05:08.588 [SageTVRequestHandler-1443:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-4.ts'...
INFO   | jvm 1    | 2016/03/23 19:06:23.684 | 19:06:23.601 [SageTVRequestHandler-1467:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-5.ts'...
INFO   | jvm 1    | 2016/03/23 19:07:13.543 | 19:07:13.448 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:14.043 | 19:07:13.949 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:14.544 | 19:07:14.449 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:07:15.045 | 19:07:14.950 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:22.394 | 19:08:22.296 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:22.894 | 19:08:22.797 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:23.395 | 19:08:23.297 [FFmpegSageTVConsumerImpl-301:DCT-HDHomeRun Prime Tuner 131C22D1-2] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/23 19:08:23.695 | 19:08:23.650 [SageTVRequestHandler-1503:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-2' to the file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-1.ts'...
INFO   | jvm 1    | 2016/03/23 19:08:24.896 | Output #0, mpegts, to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27738584-1.ts':
INFO   | jvm 1    | 2016/03/23 19:08:53.715 | 19:08:53.615 [SageTVRequestHandler-1504:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-7.ts'...
INFO   | jvm 1    | 2016/03/23 19:10:08.661 | 19:10:08.609 [SageTVRequestHandler-1540:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-8.ts'...
INFO   | jvm 1    | 2016/03/23 19:11:23.706 | 19:11:23.620 [SageTVRequestHandler-1570:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '121' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/RehabAddict-MidCenturyBathroomRemade-27737490-9.ts'...




INFO   | jvm 1    | 2016/03/24 18:55:10.277 | 18:55:10.234 [SageTVRequestHandler-9823:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-42.ts'...
INFO   | jvm 1    | 2016/03/24 18:56:40.329 | 18:56:40.240 [SageTVRequestHandler-9823:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-43.ts'...
INFO   | jvm 1    | 2016/03/24 18:58:10.280 | 18:58:10.200 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-44.ts'...
INFO   | jvm 1    | 2016/03/24 18:59:40.233 | 18:59:40.196 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '181' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/UntoldStoriesoftheER-DirectorDown-27760311-45.ts'...
INFO   | jvm 1    | 2016/03/24 19:00:00.146 | 19:00:00.073 [SageTVRequestHandler-9896:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts'...
INFO   | jvm 1    | 2016/03/24 19:00:01.547 | Output #0, mpegts, to '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts':
INFO   | jvm 1    | 2016/03/24 19:07:11.917 | 19:07:11.823 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:12.418 | 19:07:12.324 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:12.918 | 19:07:12.824 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)
INFO   | jvm 1    | 2016/03/24 19:07:13.419 | 19:07:13.324 [FFmpegSageTVConsumerImpl-9945:DCT-HDHomeRun Prime Tuner 131C22D1-0] ERROR FFmpegSageTVConsumerImpl - The file '/var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts' is missing and cannot be re-created => java.io.FileNotFoundException: /var/media/tv/NBCNightlyNewsWithLesterHolt-27762986-0.ts (Too many open files)




INFO   | jvm 1    | 2016/03/23 21:00:00.688 | 21:00:00.589 [SageTVRequestHandler-2642:DCT-HDHomeRun Prime Tuner 131C22D1-2] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '807' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-2' to the file '/var/media/tv/ModernFamily-ExpressYourself-27763018-0.ts'...
INFO   | jvm 1    | 2016/03/23 21:00:01.789 | Output #0, mpegts, to '/var/media/tv/ModernFamily-ExpressYourself-27763018-0.ts':
INFO   | jvm 1    | 2016/03/23 21:00:02.791 | 21:00:02.753 [SageTVRequestHandler-2644:DCT-HDHomeRun Prime Tuner 131C22D1-0] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '869' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-0' to the file '/var/media/tv/BeringSeaGold-DiggingDeep-27769677-0.ts'...
INFO   | jvm 1    | 2016/03/23 21:00:04.793 | Output #0, mpegts, to '/var/media/tv/BeringSeaGold-DiggingDeep-27769677-0.ts':
INFO   | jvm 1    | 2016/03/23 22:00:00.095 | 22:00:00.015 [SageTVRequestHandler-3200:DCT-HDHomeRun Prime Tuner 131C22D1-1] INFO  HDHRNativeCaptureDevice - Starting the encoding for the channel '804' from the device 'DCT-HDHomeRun Prime Tuner 131C22D1-1' to the file '/var/media/tv/ChicagoPD-KasualWithaK-27762980-0.ts'...
INFO   | jvm 1    | 2016/03/23 22:00:01.396 | Output #0, mpegts, to '/var/media/tv/ChicagoPD-KasualWithaK-27762980-0.ts':

This is the first I've seen this one. The error (Too many open files) has to do with Linux complaining that too many files are open on the file system. When the SWITCH happens, the consumer desperately tries to re-create the file because it's not growing or doesn't exist and it can't create it. The other recordings piling up are likely the result of failures to create new files and returning ERROR to SageTV. Better details are usually in opendct.log. wrapper.log will only give you an abbreviated INFO level of logging.

I personally haven't run into this error before in all my years of using Linux; I had to look the error up. lsof should get you in the right direction of what has so many files open simultaneously. Hopefully not OpenDCT. I checked the limit on one of my installs and it was in the millions, so it probably takes a lot of effort to saturate the limit.

matt91 · #**649** 03-24-2016, 08:21 PM

Quote:

Originally Posted by EnterNoEscape

This is the first I've seen this one. The error (Too many open files) has to do with Linux complaining that too many files are open on the file system. When the SWITCH happens, the consumer desperately tries to re-create the file because it's not growing or doesn't exist and it can't create it. The other recordings piling up are likely the result of failures to create new files and returning ERROR to SageTV. Better details are usually in opendct.log. wrapper.log will only give you an abbreviated INFO level of logging.

I personally haven't run into this error before in all my years of using Linux; I had to look the error up. lsof should get you in the right direction of what has so many files open simultaneously. Hopefully not OpenDCT. I checked the limit on one of my installs and it was in the millions, so it probably takes a lot of effort to saturate the limit.

Yikes. FWIW, when 16.04 comes out in a few weeks, I do plan to wipe this server and rebuild it. I do suspect that there are lots of bits and pieces that have accumulated over the years that may be causing problems.

Anyway, here is the opendct log file, in case there is anything in here that you may notice. The bulk of it are error messages between 1900 and 1908 when sage "reset" itself and started recording.

EnterNoEscape · #**650** 03-24-2016, 10:27 PM

Quote:

Originally Posted by matt91

Yikes. FWIW, when 16.04 comes out in a few weeks, I do plan to wipe this server and rebuild it. I do suspect that there are lots of bits and pieces that have accumulated over the years that may be causing problems.

Anyway, here is the opendct log file, in case there is anything in here that you may notice. The bulk of it are error messages between 1900 and 1908 when sage "reset" itself and started recording.

I should note that wrapper.log is the log generated by JSW which means that it's most helpful if something about the JVM stops working. You'll see messages about resource allocation failures and missing classes (which should never be happening in a release) that you might not see in the normal log.

I didn't really see anything any more clearly, but at least based on skimming, I didn't see OpenDCT doing anything out of the ordinary given the situation.

EnterNoEscape · #**651** 03-25-2016, 04:35 PM

Quote:

Originally Posted by EnterNoEscape

I can confirm it has a small problem at ~35 minutes (MCU commercial) and bigger one at ~56 minutes (end of a Coke commercial). I think I know what needs to be done.

Greg2dot0,

Just to give you an update. The issue you're running into technically isn't a FiOS issue. What's happening is you're getting TS packets that actually contain invalid time stamps. This could be a demodulation error, but it does seem to happen on commercials only, so it could also be a problem with the source content from Verizon or the network end. I personally still haven't seen this happen with any of my recordings yet; or at least that I know of.

I have re-written the code so it will actually correct time stamps by applying an offset that moves them to where they should be. If there are sufficient errors of this type, even after fixing it, you may get a blip in audio at least when the issue started. After running your recording and several other samples unrelated to your case, they all came out clean and still playback ok on the Android miniclient which is something I've added to my checklist. The log will let you know when there's something inconsistent that it's fixing. The "resync" did not have any ill-effects that I found in the A/V sync either which is always a plus. I hope that this fix will address the problem sufficiently since I don't really want to write special code paths for various content if I can avoid it.

Just as a fun fact, VideoRedo did not like your recording at all. It basically gave up on it. That's fairly rare in my experience. Whenever I get an interesting recording, one thing I sometimes do is run it though VideoRedo to see if it can improve the recording. I figure that if it can't fix it, there's a good chance I'm not going to be able to fix it either. This time would be an exception.

I'm going to run this code on my own equipment for a little longer before I release a new RC to try to make sure it doesn't have any unexpected side-effects.

Cooper · #**652** 03-25-2016, 04:58 PM

First off great work on this as I moved from SageDCT a month or so ago and has worked pretty well. We have started noticing when watching live TV and when pausing on and off once the show that is on is finished sage will pop back to the guide instead of just playing through to the next show that is on but continues to record and you have to select in the guide to continue watching.

I don't remembering this happening in the past and wanted to check if this is a know problem? I have not changed any of the default properties and using the most current Beta. I'm currently using 2 Homerun Primes and Homerun Extend.

Thanks

EnterNoEscape · #**653** 03-25-2016, 05:22 PM

Quote:

Originally Posted by Cooper

First off great work on this as I moved from SageDCT a month or so ago and has worked pretty well. We have started noticing when watching live TV and when pausing on and off once the show that is on is finished sage will pop back to the guide instead of just playing through to the next show that is on but continues to record and you have to select in the guide to continue watching.

I don't remembering this happening in the past and wanted to check if this is a know problem? I have not changed any of the default properties and using the most current Beta. I'm currently using 2 Homerun Primes and Homerun Extend.

Thanks

That's odd. That's one of the things I test constantly. There will be a move to the transcoding consumer when I move on to 0.5 because I have improved so much and it doesn't make sense to keep them synced up when they effectively do the same thing when remuxing. Try changing all of the values for sagetv.device.<unique_id>.consumer to opendct.consumer.FFmpegTransSageTVConsumerImpl and see if the situation improves. The difference is that it performs SWITCH more accurately on the key frames.

The reason why you would have never seen this in SageDCT is because it didn't support SWITCH which is why you get that brief interruption between recordings when watching live.

troll5501 · #**654** 03-26-2016, 08:22 AM

I've run into another issue. It's also related to "too many open files", but I think for a different reason than matt91.

Early today my recording directory ran out of space (NFS mount). This triggered a "java.io.IOException: No space left on device" in OpenDCT. Looking at the code, I think when this happens it tries to open the file again but never closes the previous file handle(s). The result is that the OpenDCT jvm process now has 4096 open files (most are pointing to files on my NFS share) and has reached the user limit.

Code:

[root@sagelinux conf]# ls -ltr /proc/16079/fd | wc -l
4097

Here is a snippet from the OpenDCT log:

Code:

03:29:24.916 [SageTVSocketServer-54:9000] ERROR SageTVSocketServer - Unable to accept connections on port 9000 => java.net.SocketException: Too many open files
03:29:24.916 [SageTVSocketServer-54:9000] INFO  SageTVSocketServer - Re-opening ServerSocket on port 9000...
03:29:24.987 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - File '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' write failed => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

03:29:25.150 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - File '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' write failed => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

03:29:25.151 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - Unable to re-open file '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

I'm using the FFmpegTransSageTVConsumerImpl consumer. Here is the code block that the full disk appears to be triggering:

Code:

 public void failed(Throwable e, Object attachment) {
                    logger.error("File '{}' write failed => ", directFilename, e);

                    try {
                        asyncFileChannel = AsynchronousFileChannel.open(
                                Paths.get(directFilename),
                                StandardOpenOption.WRITE,
                                StandardOpenOption.CREATE);
                    } catch (IOException e1) {
                        logger.error("Unable to re-open file '{}' => ", directFilename, e);
                    }

                    try {
                        buffers.put((ByteBuffer)attachment);
                    } catch (InterruptedException e0) {
                        logger.debug("Interrupted while returning byte buffer to queue => ", e0);
                    }
                }

Should there be a close() call in here somewhere? And maybe after any other file-related failures and failed open attempts, just to be sure nothing is left open? I haven't looked at the other consumers code, but the issue may exist there too.

EnterNoEscape · #**655** 03-26-2016, 08:33 AM

Quote:

Originally Posted by troll5501

I've run into another issue. It's also related to "too many open files", but I think for a different reason than matt91.

Early today my recording directory ran out of space (NFS mount). This triggered a "java.io.IOException: No space left on device" in OpenDCT. Looking at the code, I think when this happens it tries to open the file again but never closes the previous file handle(s). The result is that the OpenDCT jvm process now has 4096 open files (most are pointing to files on my NFS share) and has reached the user limit.

Code:

[root@sagelinux conf]# ls -ltr /proc/16079/fd | wc -l
4097

Here is a snippet from the OpenDCT log:

Code:

03:29:24.916 [SageTVSocketServer-54:9000] ERROR SageTVSocketServer - Unable to accept connections on port 9000 => java.net.SocketException: Too many open files
03:29:24.916 [SageTVSocketServer-54:9000] INFO  SageTVSocketServer - Re-opening ServerSocket on port 9000...
03:29:24.987 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - File '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' write failed => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

03:29:25.150 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - File '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' write failed => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

03:29:25.151 [Thread-15853] ERROR FFmpegTransSageTVConsumerImpl - Unable to re-open file '/sagedata/UnsungHollywood-FlipWilson-38088719-0.ts' => java.io.IOException: No space left on device
        at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
        at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SimpleAsynchronousFileChannelImpl$3.run(SimpleAsynchronousFileChannelImpl.java:374)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

I'm using the FFmpegTransSageTVConsumerImpl consumer. Here is the code block that the full disk appears to be triggering:

Code:

 public void failed(Throwable e, Object attachment) {
                    logger.error("File '{}' write failed => ", directFilename, e);

                    try {
                        asyncFileChannel = AsynchronousFileChannel.open(
                                Paths.get(directFilename),
                                StandardOpenOption.WRITE,
                                StandardOpenOption.CREATE);
                    } catch (IOException e1) {
                        logger.error("Unable to re-open file '{}' => ", directFilename, e);
                    }

                    try {
                        buffers.put((ByteBuffer)attachment);
                    } catch (InterruptedException e0) {
                        logger.debug("Interrupted while returning byte buffer to queue => ", e0);
                    }
                }

Should there be a close() call in here somewhere? And maybe after any other file-related failures and failed open attempts, just to be sure nothing is left open? I haven't looked at the other consumers code, but the issue may exist there too.

Good catch. My understanding is that if there was an IO exception, the handle has already been dropped, but maybe that's not the case. I did not verify this, so I'll have it close the files just in case. Thanks!

The other half of it is if there's an IO exception, the value of asyncFileChannel is going to be null, so if the JVM isn't managing the situation, then we have a different problem. asyncFileChannel however would not be null just prior to that since it was called to write to the file, so I did add for it to be closed after that particular exception happens. None of the other consumers use the async write method, so this would be the only one that should be able to cause this issue. I went over the other ones to see if I missed anything, but they don't look like they have anything that might put us in a similar situation.

troll5501 · #**656** 03-26-2016, 10:16 AM

Quote:

Originally Posted by EnterNoEscape

Good catch. My understanding is that if there was an IO exception, the handle has already been dropped, but maybe that's not the case. I did not verify this, so I'll have it close the files just in case. Thanks!

The other half of it is if there's an IO exception, the value of asyncFileChannel is going to be null, so if the JVM isn't managing the situation, then we have a different problem. asyncFileChannel however would not be null just prior to that since it was called to write to the file, so I did add for it to be closed after that particular exception happens. None of the other consumers use the async write method, so this would be the only one that should be able to cause this issue. I went over the other ones to see if I missed anything, but they don't look like they have anything that might put us in a similar situation.

Thanks for the quick response! I'll test the same scenario when you have the next build ready.

Greg2dot0 · #**657** 03-26-2016, 11:07 AM

Quote:

Originally Posted by EnterNoEscape

Greg2dot0,

Just to give you an update. The issue you're running into technically isn't a FiOS issue. What's happening is you're getting TS packets that actually contain invalid time stamps. This could be a demodulation error, but it does seem to happen on commercials only, so it could also be a problem with the source content from Verizon or the network end. I personally still haven't seen this happen with any of my recordings yet; or at least that I know of.

I have re-written the code so it will actually correct time stamps by applying an offset that moves them to where they should be. If there are sufficient errors of this type, even after fixing it, you may get a blip in audio at least when the issue started. After running your recording and several other samples unrelated to your case, they all came out clean and still playback ok on the Android miniclient which is something I've added to my checklist. The log will let you know when there's something inconsistent that it's fixing. The "resync" did not have any ill-effects that I found in the A/V sync either which is always a plus. I hope that this fix will address the problem sufficiently since I don't really want to write special code paths for various content if I can avoid it.

Sounds like something is really screwed up somewhere..

Quote:

Originally Posted by EnterNoEscape

I'm going to run this code on my own equipment for a little longer before I release a new RC to try to make sure it doesn't have any unexpected side-effects.

Take as long as you need, this is on my test box. While I experience some weirdness occasionally using PrimeNetEncoder, this is working for the most part. For the longer term solution, I want to move Sage off my Windows 10 box and onto Linux 64.

Thanks for all your hard work on what is hopefully a "fringe" case.

EnterNoEscape · #**658** 03-26-2016, 11:36 AM

Quote:

Originally Posted by Greg2dot0

Sounds like something is really screwed up somewhere..

I found a channel that positively breaks things the way you've experienced fairly quickly. Channel 500 is an ad for Quantum FiOS that loops. Every time it loops back, it just goes back to the first dts in the video which is a little wrong and enough to throw the old consumer dts handling off every single time. I've been playing with this channel all morning and the changes are working extremely well. There is a small speed up for a second when the video loops back because OpenDCT is basically guessing what the next time stamp should be and I suspect there may be a gap between the audio and video when it loops (one stream is longer than the other). I didn't see this happen on the recording you sent me.

Quote:

Originally Posted by troll5501

Thanks for the quick response! I'll test the same scenario when you have the next build ready.

You got me curious about some things regarding file handles in Linux. I noticed when I use upload id, SageTV creates a lot of handles (> 50) just for that one file. I suspect that's something Java is doing since I know that SageTV is using a FileChannel to write out the file and doesn't do anything particularly interesting other than not inform you of an error while writing. In comparison, Comskip only has 4 handles on the same file.

EnterNoEscape · #**659** 03-26-2016, 08:28 PM

If you've been having the kinds of issues described by Greg2dot0 and troll5501, try changing the values of sagetv.device.<unique_id>.consumer to opendct.consumer.FFmpegTransSageTVConsumerImpl with this release.

FFmpeg transcoding consumer can now fix invalid dts issues.

The HDHomeRun discovery method now only runs at startup, after standby and if a device is not responding. This should help keep the UDP traffic to a minimum.

Auto-ClearQAM mapping by tuning is now enabled by default. This won't do anything like try to use a tuner that's locked by another program, so it's unlikely to ever be an issue.

The default wait before returning OK to SageTV regardless of if the consumer says it's streaming or not is now 8500ms for all capture device implementations. 5000ms was too low in some cases.

Fixed the file not being closed before re-opening when the async writer in the FFmpeg transcoder fails to write. Thanks troll5501.

Fixed a potential hang when getting the status if an InfiniTV device is not responding.

Capture device pooling is now considered stable.

Greg2dot0 · #**660** 03-27-2016, 06:25 AM

Installed RC3 and deleted my existing opendct.properties file and came across some issues

First off, at 06:00:

06:00:03.562 [FFmpegSageTVConsumerImpl-98

CT-HDHomeRun Prime Tuner 13142E5A-0] WARN FFmpegSageTVConsumerImpl - Consumer created an IO exception => java.nio.channels.ClosedByInterruptException
at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:202)
at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:216)
at opendct.consumer.FFmpegSageTVConsumerImpl.writeBuffer(FFmpegSageTVConsumerImpl.java:766)
at opendct.consumer.FFmpegSageTVConsumerImpl.access$900(FFmpegSageTVConsumerImpl.java:49)
at opendct.consumer.FFmpegSageTVConsumerImpl$WriteCallback.call(FFmpegSageTVConsumerImpl.java:559)
at org.bytedeco.javacpp.avformat.av_interleaved_write_frame(Native Method)
at opendct.consumer.FFmpegSageTVConsumerImpl.remuxRtpPackets(FFmpegSageTVConsumerImpl.java:1217)
at opendct.consumer.FFmpegSageTVConsumerImpl.run(FFmpegSageTVConsumerImpl.java:269)
at java.lang.Thread.run(Thread.java:745)

06:00:03.563 [FFmpegSageTVConsumerImpl-98

CT-HDHomeRun Prime Tuner 13142E5A-0] ERROR FFmpegSageTVConsumerImpl - Error -541478725 while writing packet at input stream offset 1225060640.

This doesn't seem to be related to the issue I was having but may be related to the change in shows.

But, at 6:47, it looks like the old issue is still here:

06:47:49.348 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] WARN ffmpeg - [mpegts @ 0x7f9bd0057ea0] PES packet size mismatch
06:47:55.617 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] WARN ffmpeg - [mpegts @ 0x7f9bd0057ea0] Invalid timestamps stream=1379733664, pts=(null), dts=(null), size=0
06:47:55.701 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] WARN ffmpeg - [mpegts @ 0x7f9bd0057ea0] DTS 140309371359392 < 0 out of order
06:47:55.701 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] ERROR ffmpeg - [mpegts @ 0x7f9bd005b860] Application provided invalid, non monotonically increasing dts to muxer in stream 1379733664: (null) >= (null)
06:47:55.701 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] ERROR FFmpegSageTVConsumerImpl - Error -22 while writing packet at input stream offset 2924624068.
06:47:55.732 [FFmpegSageTVConsumerImpl-562

CT-HDHomeRun Prime Tuner 13142E5A-1] ERROR FFmpegSageTVConsumerImpl - Error -22 while writing packet at input stream offset 2924636476.

The log is attached.

Similar Threads
Thread	Thread Starter	Forum	Replies	Last Post
ATI TV Wonder Digital Cable Tuner & SageTV	nyle	Hardware Support	4	02-17-2009 10:12 PM
ATI TV Wonder Digital Cable Tuner	rajczi	Hardware Support	4	01-14-2008 08:24 PM
ATI TV Wonder™ Digital Cable Tuner	dadams	Hardware Support	4	01-09-2007 10:55 AM
Digital Cable - one guide - need HD on one tuner reg tv on other	Kimper	SageTV Beta Test Software	14	11-27-2006 08:15 PM
Multi-tuner Digital Cable	mlbdude	SageTV Software	0	06-26-2003 01:08 PM

Currently Active Users Viewing This Thread: 5 (0 members and 5 guests)