Fork of SageTV MiniClient for Android TV

[hb4]

Originally Posted by jvl711

When you say it is hanging, are you seeing the spinning circle? Does this happening when navigating or when watching video? If you are seeing hang detected in the server logs, I think that is generally a server side issue I think... I also noticed that you are using one of the testing version of Sage.jar. I think there are newer versions than that one that have all of the features in it.

Josh

Yes, spinning circle...
After searching for 'new router', I (re)discovered that the windows firewall should be disabled. I did that, and was able to bring up the Sage Client on my server, and did not see a spinning circle on the FS4K (although I did not always see it before). Hopefully that fixes it.

I will look for a newer Sage.jar. <EDIT:> Found it (first post).

[wnjj]

Looking further it seems that setting the audio may be the first thing the server “pushes” to the client which does point to a network issue.

[ojones]

I have now replicated this on a fully updated NVidia Shield 4k as well as Kindle Fire HD7 tablet and several Sony TVs running Android.

Looks like the failure occurs right after the audio setting. I had tested 1.80x extensively using a fast fiber to fiber wan link and it worked well.

I have not updated Java recently (running 9.2.4 x64 server on w2016 in a VM on heavy duty hardware). I think we can rule out HD failures and networking hardware as several of us are seeing the same issue.

I have occaisonally been able to get the first file to play perfetly (play, pause, FF / RW, comskip jump) then the second file just has the spinning wheel and then exits back to the launcher.

Thu 7/8 16:02:55.237 [VideoFrame-4c4b424c4141@25380992] VideoFrame.timeSelected(Thu 7/1 20:02:43.541, true) currFile=MediaFile[id=47665851 A[47105309,47099683,"Making It",19613@0701.20:00,60,T] mask=TV host=Workspace-1 encodedBy=DCT-Ceton InfiniTV Ethernet (00-80-8a-76) Tuner 1 on 192.168.45.60:9000 WCAUDT format=MPEG2-TS 0:00:01 9227 kbps [#0 Video[H.264 29.97003 fps 1920x1080 16:9 progressive id=100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps idx=1 id=101 eng]#2 Audio[AC3 48000 Hz 1 channels 96 kbps idx=2 id=102 spa]{ScrapedBy=Phoenix, IMDBID=, SeasonFinal=false, CollectionName=, MediaType=TV, EpisodeCount=0, CollectionOverview=, ScrapedDate=1625187601617, MediaProviderDataID=338260, MediaTitle=Making It, SeriesInfoID=14154367, TagLine=, UserRating=0, DiscNumber=0, CollectionID=0, MediaProviderID=tvdb, TrailerUrl=}] \\workspace-1\tv-rec2\MakingIt-S03E02-RandomCraftsofKindness-47105309-0.ts, Seg0[Thu 7/1 20:00:00.007-Thu 7/1 21:00:00.039]]
Thu 7/8 16:02:55.238 [VideoFrame-4c4b424c4141@25380992] initDriver0()
Thu 7/8 16:02:55.238 [VideoFrame-4c4b424c4141@25380992] Issuing MCSR client socket to 4c4b424c4141
Thu 7/8 16:02:55.238 [VideoFrame-4c4b424c4141@25380992] MiniPlayer established for 4c4b424c4141
Thu 7/8 16:02:55.312 [VideoFrame-4c4b424c4141@25380992] getEstimatedBW=1748904 estimatedBWBytes=218613 estimatedBWTime=1000
Thu 7/8 16:02:55.313 [VideoFrame-4c4b424c4141@25380992] MiniPlayer got an estimate from the UI on bandwidth of 1748Kbps
Thu 7/8 16:02:55.313 [VideoFrame-4c4b424c4141@25380992] MiniPlayer is using Push mode playback
Thu 7/8 16:02:55.313 [VideoFrame-4c4b424c4141@25380992] MiniPlayer is using the transcoder
Thu 7/8 16:02:55.313 [VideoFrame-4c4b424c4141@25380992] Overriding transcode mode because a fixed format was set by client
Thu 7/8 16:02:55.314 [VideoFrame-4c4b424c4141@25380992] Mpeg2Reader is detecting timestamp boundaries in the file...
Thu 7/8 16:02:55.314 [VideoFrame-4c4b424c4141@25380992] IFrame alignment=false
Thu 7/8 16:02:55.314 [VideoFrame-4c4b424c4141@25380992] Opened MPEG-2 PS file: \\workspace-1\tv-rec2\MakingIt-S03E02-RandomCraftsofKindness-47105309-0.ts firstPTS=45000 durationMsec=-1
Thu 7/8 16:02:55.314 [VideoFrame-4c4b424c4141@25380992] openURL0(push
Thu 7/8 16:02:55.389 [VideoFrame-4c4b424c4141@25380992] Switching audio stream to be 0xbd-80 for default AC3
Thu 7/8 16:02:55.389 [VideoFrame-4c4b424c4141@25380992] Setting audio stream for playback to be ID=0xbd80
Thu 7/8 16:02:56.519 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 751 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:02:57.270 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 1502 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:02:58.020 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 2252 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:02:58.026 [Fork-OPUS4-112742@716be27a] ENDING background recording thumb preloader thread, ID = 0.33190992059478475
Thu 7/8 16:02:58.770 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 3002 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:02:59.521 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 3753 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:00.271 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 4503 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:01.022 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 5254 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:01.773 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 6005 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:02.524 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 6756 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:03.274 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 7506 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:04.024 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 8256 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:04.774 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 9006 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:05.524 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 9756 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:06.275 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 10507 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:07.025 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 11257 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:07.776 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 12008 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:08.526 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 12758 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:09.276 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 13508 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:10.027 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 14259 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:10.777 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 15009 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:11.528 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 15760 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:12.279 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 16511 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:13.030 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 17262 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:13.630 [Timer-9@388d1f0] Screen Saver Timeout expired....tv=false playin=false fs=true sleepy=false currSS=true fsVideo=false
Thu 7/8 16:03:13.780 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 18012 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:14.530 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 18762 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:15.281 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 19513 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:16.031 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 20263 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:16.781 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 21013 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:17.470 [Thread-5546@518f428] CD: ComskipJob.updateRatio: Old, Current and new Ratios 0.09821219:0.058333334:0.094224304
Thu 7/8 16:03:17.531 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 21763 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:18.281 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 22513 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:19.032 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 23264 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:19.783 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 24015 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:20.534 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 24766 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:21.284 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 25516 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:22.035 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 26267 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:22.785 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 27017 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:23.535 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 27767 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:24.286 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 28518 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:25.036 [AWTThreadWatcher-4c4b424c4141@57d49622] EventThread-4c4b424c4141 Hang Detected - hang time = 29268 UILocker=Thread[ActiveRender-4c4b424c4141,2,main]
Thu 7/8 16:03:25.392 [TimeoutHandler@1bb028f] TIMEOUT occurred - close the socket asynchronously for java.nio.channels.SocketChannel[connected local=/192.168.45.59:31099 remote=/24.11.139.54:1646]
Thu 7/8 16:03:25.393 [VideoFrame-4c4b424c4141@25380992] Error with MiniPlayer, closing UI: java.nio.channels.AsynchronousCloseException

[jvl711]

Originally Posted by wnjj

Based upon the logs shown above, it’s hanging when trying to set the audio stream type here:

https://github.com/google/sagetv/blo...yer.java#L3685

Which is called from here:

https://github.com/google/sagetv/blo...yer.java#L1396

I’m not sure if that is a coincidence that happens when something else hangs the system but the 30 seconds of hang triggers a timeout and the exception kicks in there.

I did not look close enough at the logs. You are 100% correct. It appears to be chocking when selecting the audio track. This is pretty normal action, so I am not sure if it is a coincidence, a bad file, network hiccup or an issue with the Client.

I think at that point the client might not even have the file loaded for playback. In that event I think I actually just store the value and set the track after it is done loading. If this is reproduceable with a specific file or scenario I can look into it further.

Josh

[jvl711]

To those experiencing the Hang issue, is this possibly happening on files that have subtitles? More specifically forced subtitles? Or do you have subtitles defaulted to on?

EDIT: Can I get a confirmation on which version of the client you guys are using...

Thanks,
Josh

[ojones]

Josh - Where would we look for that setting? Sorry for a silly question!

I don't have anything enabled in the client that I know about.

Is it a Sage.Properties setting or would it be something inherited from the settings in OpenDCT?

[ojones]

Client 1.8.1 & server 9.2.4

[ojones]

Josh - I just returned home from traveling and could retest the same firehd7 and nvidia shield using forced transcode on my lan link (even used the same test files plus new ones).

This time it worked perfectly so seems to be a wan issue. Any chance their is a minimum bandwidth test that could be failing on the wan link? The bandwidth test showing in the log was bogus but reported speeds under 2mb/s which is way below the actual link speed.

[ojones]

Here is the log snippet from lan playback (believe it is transcoding but not positive). Odd still one hang but it isn't repeated.

Sat 7/10 15:15:03.392 [VideoFrame-58434e505141@68370db2] initDriver0()
Sat 7/10 15:15:03.392 [VideoFrame-58434e505141@68370db2] Issuing MCSR client socket to 58434e505141
Sat 7/10 15:15:03.392 [VideoFrame-58434e505141@68370db2] MiniPlayer established for 58434e505141
Sat 7/10 15:15:03.395 [VideoFrame-58434e505141@68370db2] getEstimatedBW=0 estimatedBWBytes=0 estimatedBWTime=0
Sat 7/10 15:15:03.396 [VideoFrame-58434e505141@68370db2] MiniPlayer was not able to get a bandwidth estimate from the UI system, sending data to get its own estimate...
Sat 7/10 15:15:03.398 [VideoFrame-58434e505141@68370db2] Not using optimized bandwidth detection because the numbers didn't align
Sat 7/10 15:15:03.399 [VideoFrame-58434e505141@68370db2] Bandwidth test base=0 base*2=0 BW=131168000
Sat 7/10 15:15:03.399 [VideoFrame-58434e505141@68370db2] MiniPlayer got an estimate from the UI on bandwidth of 131168Kbps
Sat 7/10 15:15:03.399 [VideoFrame-58434e505141@68370db2] MiniPlayer is using Push mode playback
Sat 7/10 15:15:03.399 [VideoFrame-58434e505141@68370db2] MiniPlayer is using the transcoder
Sat 7/10 15:15:03.399 [VideoFrame-58434e505141@68370db2] Overriding transcode mode because a fixed format was set by client
Sat 7/10 15:15:03.400 [VideoFrame-58434e505141@68370db2] Mpeg2Reader is detecting timestamp boundaries in the file...
Sat 7/10 15:15:03.400 [VideoFrame-58434e505141@68370db2] IFrame alignment=false
Sat 7/10 15:15:03.400 [VideoFrame-58434e505141@68370db2] Opened MPEG-2 PS file: \\workspace-1\tv-rec2\BeachfrontBargainHuntRenovation-S03E11-MakeoverinMathewsVirginia-46929369-0.ts firstPTS=45000 durationMsec=-1
Sat 7/10 15:15:03.401 [VideoFrame-58434e505141@68370db2] openURL0(push
Sat 7/10 15:15:03.402 [VideoFrame-58434e505141@68370db2] Switching audio stream to be 0xbd-80 for default AC3
Sat 7/10 15:15:03.403 [VideoFrame-58434e505141@68370db2] Setting audio stream for playback to be ID=0xbd80
Sat 7/10 15:15:03.404 [VideoFrame-58434e505141@68370db2] Sigma video dim=java.awt.Dimension[width=720,height=480]
Sat 7/10 15:15:03.404 [VideoFrame-58434e505141@68370db2] pausePush0()
Sat 7/10 15:15:03.405 [VideoFrame-58434e505141@68370db2] setMute0()
Sat 7/10 15:15:03.406 [VideoFrame-58434e505141@68370db2] getDuration : 0
Sat 7/10 15:15:03.406 [VideoFrame-58434e505141@68370db2] VideoFrame.timeSelected2(Sun 6/13 13:00:00.004, true) currFile=MediaFile[id=47047527 A[46929369,46875193,"Beachfront Bargain Hunt: Renovation",67375@0613.13:00,60,T] mask=TV host=Workspace-1 encodedBy=DCT-Ceton InfiniTV Ethernet (00-80-8a-76) Tuner 1 on 192.168.45.60:9000 DIYHD format=MPEG2-TS 0:00:01 12604 kbps [#0 Video[H.264 29.97003 fps 1920x1080 16:9 progressive id=100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps idx=1 id=101 eng]#2 Audio[AC3 48000 Hz 2 channels 192 kbps idx=2 id=102 eng]{ScrapedBy=Phoenix, IMDBID=, SeasonFinal=false, CollectionName=, MediaType=TV, EpisodeCount=0, CollectionOverview=, ScrapedDate=1623607205708, MediaProviderDataID=315689, MediaTitle=Beachfront Bargain Hunt: Renovation, SeriesInfoID=12110823, TagLine=, UserRating=0, DiscNumber=0, CollectionID=0, MediaProviderID=tvdb, TrailerUrl=}] \\workspace-1\tv-rec2\BeachfrontBargainHuntRenovation-S03E11-MakeoverinMathewsVirginia-46929369-0.ts, Seg0[Sun 6/13 13:00:00.004-Sun 6/13 14:00:00.011]] realDur=0
Sat 7/10 15:15:03.406 [VideoFrame-58434e505141@68370db2] seeking numpushbuffers=0 seekTime=0
Sat 7/10 15:15:03.406 [VideoFrame-58434e505141@68370db2] Mpeg2Reader seeking to pos=0
Sat 7/10 15:15:03.406 [VideoFrame-58434e505141@68370db2] Using 7 threads for the transcoder
Sat 7/10 15:15:03.535 [Fork-OPUS4-112742@15018571] ENDING background recording thumb preloader thread, ID = 0.2610373263785213
Sat 7/10 15:15:04.378 [AWTThreadWatcher-58434e505141@595ccd02] EventThread-58434e505141 Hang Detected - hang time = 751 UILocker=Thread[ActiveRender-58434e505141,2,main]
Sat 7/10 15:15:04.391 [VideoFrame-58434e505141@68370db2] File Format Parsed3 \\workspace-1\tv-rec2\BeachfrontBargainHuntRenovation-S03E11-MakeoverinMathewsVirginia-46929369-0.ts=MPEG2-TS 0:59:06 18284 kbps [#0 Video[H.264 29.97 fps 1920x1080 16:9 progressive id=100]#1 Audio[AC3 48000 Hz idx=1 id=101 eng]#2 Audio[AC3 48000 Hz 2 channels idx=2 id=102 eng]{Language=eng}]
Sat 7/10 15:15:04.396 [VideoFrame-58434e505141@68370db2] flushPush0()
Sat 7/10 15:15:04.397 [VideoFrame-58434e505141@68370db2] Creating new push thread
Sat 7/10 15:15:04.398 [VideoFrame-58434e505141@68370db2] playPush0()
Sat 7/10 15:15:04.398 [Pusher@35a9fbbc] Pusher thread is starting
Sat 7/10 15:15:04.399 [Pusher@35a9fbbc] Miniplayer pusher using buffer size of 32768

[jvl711]

Originally Posted by ojones

Josh - Where would we look for that setting? Sorry for a silly question!

I don't have anything enabled in the client that I know about.

Is it a Sage.Properties setting or would it be something inherited from the settings in OpenDCT?

The forced subtitiles is something that I added to SageTV. It is when there is a subtitle track mark as "Always Show" or "Forced". It is generally when there is a laguage spoken that is not the default language. If you are using my format detector, and encounter one of these scenarios is when it would happen generally.

Thanks,
Josh

[hb4]

Client 1.8.1

I updated the SageTVTranscoder plugin and now it seems the WAN connection is always hanging. Here is one instance.

SageTV Placeshifter also hangs.

I updated the Jar as you suggested earlier.

The miniclient on the FS4K was working perfectly until a few weeks ago. The only change I have made beyond the ones above was updating my router. I think the client was updated around that time as well (it must update automatically).

I believe the subtitle setting is only accessed while a video is playing. Now that all of them seem to be hanging, I won't be able to check that setting.

Mon 7/12 12:36:33.312 [AsyncWatch@17136bf] watchThisFile=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]]
Mon 7/12 12:36:33.316 [AsyncWatch@17136bf] Watch airing is a file & over, do that instead dvd=false
Mon 7/12 12:36:33.320 [AsyncWatch@17136bf] Seeker.finishWatch(UIManager:localhost@@545352504a49-1770c24)
Mon 7/12 12:36:33.324 [AsyncWatch@17136bf] VF.submitJob(VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] ifn=null])
Mon 7/12 12:36:33.328 [VideoFrame-545352504a49@138283] VF processing job VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] ifn=null] nPlayin=false
Mon 7/12 12:36:33.332 [AsyncWatch@17136bf] No Start on Watch
Mon 7/12 12:36:33.335 [VideoFrame-545352504a49@138283] VF processing on UI Thread VFJob[WatchMF r=0.0 t=0 file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] ifn=null]
Mon 7/12 12:36:33.339 [AsyncWatch@17136bf] Deriving FreeType font face for fonts\DejaVuSansMono size=15 style=0 from=C:\Program Files (x86)\SageTV\SageTV\fonts\DejaVuSansMono.ttf
Mon 7/12 12:36:33.343 [VideoFrame-545352504a49@138283] VF processing job VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] ifn=null] nPlayin=false
Mon 7/12 12:36:33.346 [AsyncWatch@17136bf] Loading new font to cache font=MetaFont[fonts\DejaVuSansMono, size=15, style=0, height=17.0, ascent=14.0, descent=4.0, leading=-1.0, class=class sage.FreetypeFont]
Mon 7/12 12:36:33.350 [VideoFrame-545352504a49@138283] VF network encoder playback detected: true
Mon 7/12 12:36:33.354 [VideoFrame-545352504a49@138283] VF processing on UI Thread VFJob[LoadMF r=0.0 t=0 file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] ifn=null]
Mon 7/12 12:36:33.357 [AsyncWatch@17136bf] setUI(sage.PseudoMenu@c1001e[MediaPlayer OSD]) histIdx=2 uiHistory=[sage.PseudoMenu@7b2e49[SageRecordings w/ Optional Preview & AutoCategories], sage.PseudoMenu@d4aa1f[MediaFileList], sage.PseudoMenu@c1001e[MediaPlayer OSD]] redo=false performingActivation=null
Mon 7/12 12:36:33.361 [VideoFrame-545352504a49@138283] VideoFrame creating new media player for file:MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]]
Mon 7/12 12:36:33.365 [VideoFrame-545352504a49@138283] JVL - ELSE BLOCK Creating MiniPlayer
Mon 7/12 12:36:33.368 [AsyncWatch@17136bf] Deriving FreeType font face for fonts\DejaVuSansMono size=33 style=0 from=C:\Program Files (x86)\SageTV\SageTV\fonts\DejaVuSansMono.ttf
Mon 7/12 12:36:33.372 [AsyncWatch@17136bf] Loading new font to cache font=MetaFont[fonts\DejaVuSansMono, size=33, style=0, height=38.0, ascent=31.0, descent=8.0, leading=-1.0, class=class sage.FreetypeFont]
Mon 7/12 12:36:33.377 [VideoFrame-545352504a49@138283] VF file=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] targetTime = Fri 7/9 18:00:00.022
Mon 7/12 12:36:33.381 [VideoFrame-545352504a49@138283] VideoFrame.timeSelected(Fri 7/9 18:00:00.022, true) currFile=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]]
Mon 7/12 12:36:33.385 [VideoFrame-545352504a49@138283] initDriver0()
Mon 7/12 12:36:33.388 [VideoFrame-545352504a49@138283] Issuing MCSR client socket to 545352504a49
Mon 7/12 12:36:33.393 [VideoFrame-545352504a49@138283] MiniPlayer established for 545352504a49
Mon 7/12 12:36:33.415 [VideoFrame-545352504a49@138283] Supported push containers: [MPEG2-TS, MPEG2-PS, MPEG1-PS]
Mon 7/12 12:36:33.419 [VideoFrame-545352504a49@138283] ******************************* Investigating PULL/PUSH and supported codecs **********************************
Mon 7/12 12:36:33.423 [VideoFrame-545352504a49@138283] Determining if MPEG4_VIDEO is supported clientCanDoMpeg4
Mon 7/12 12:36:33.426 [VideoFrame-545352504a49@138283] 	clientCanDoMpeg4: true
Mon 7/12 12:36:33.429 [VideoFrame-545352504a49@138283] Determining if the client can do pull. Determined if there is a hostname, and it starts with file://
Mon 7/12 12:36:33.433 [VideoFrame-545352504a49@138283] 	Since we are not local, checking to see if container format is suppoted.
Mon 7/12 12:36:33.437 [VideoFrame-545352504a49@138283] JVL: PullContainers: [MP3, WMV, AC3, AAC, MATROSKA, QUICKTIME, ASF, FLAC, FLASHVIDEO, WAV, OGG]
Mon 7/12 12:36:33.440 [VideoFrame-545352504a49@138283] 		CurrentContainer: MPEG2-TS
Mon 7/12 12:36:33.443 [VideoFrame-545352504a49@138283] 		clientDoesPull: false
Mon 7/12 12:36:33.447 [VideoFrame-545352504a49@138283] Fixed push format setting from client: container=matroska;videobitrate=2000000;fps=SOURCE;bframes=0;resolution=720;audiocodec=ac3;audiobitrate=128000;audiochannels=2;
Mon 7/12 12:36:33.450 [VideoFrame-545352504a49@138283] Fixed push format setting from client: container=matroska;videobitrate=2000000;fps=SOURCE;bframes=0;resolution=720;audiocodec=ac3;audiobitrate=128000;audiochannels=2;
Mon 7/12 12:36:33.453 [VideoFrame-545352504a49@138283] Checking bandwidth to the client
Mon 7/12 12:36:33.457 [VideoFrame-545352504a49@138283] getEstimatedBW=0 estimatedBWBytes=0 estimatedBWTime=0
Mon 7/12 12:36:33.460 [VideoFrame-545352504a49@138283] Bandwidth: 0
Mon 7/12 12:36:33.463 [VideoFrame-545352504a49@138283] 	Bandwidth is < 500000 and client can do mpeg4 or httpls
Mon 7/12 12:36:33.467 [VideoFrame-545352504a49@138283] MiniPlayer was not able to get a bandwidth estimate from the UI system, sending data to get its own estimate...
Mon 7/12 12:36:33.581 [VideoFrame-545352504a49@138283] Bandwidth test base=29 base*2=31 BW=4523034
Mon 7/12 12:36:33.585 [VideoFrame-545352504a49@138283] MiniPlayer got an estimate from the UI on bandwidth of 4523Kbps
Mon 7/12 12:36:33.591 [VideoFrame-545352504a49@138283] Checking for low bandwidth (local client, MiniClient, supports push MPEG2_TS or MPEG2_PS, less than required bandwidth and MPEG4)
Mon 7/12 12:36:33.597 [VideoFrame-545352504a49@138283] 	pureLocal: false
Mon 7/12 12:36:33.604 [VideoFrame-545352504a49@138283] 	MiniClient Renderer is not null: true
Mon 7/12 12:36:33.610 [VideoFrame-545352504a49@138283] Supported push containers: [MPEG2-TS, MPEG2-PS, MPEG1-PS]
Mon 7/12 12:36:33.617 [VideoFrame-545352504a49@138283] 	MPEG2_PS Support: true
Mon 7/12 12:36:33.621 [VideoFrame-545352504a49@138283] Supported push containers: [MPEG2-TS, MPEG2-PS, MPEG1-PS]
Mon 7/12 12:36:33.625 [VideoFrame-545352504a49@138283] 	MPEG2_TS Support: true
Mon 7/12 12:36:33.629 [VideoFrame-545352504a49@138283] 	IsLowBandwidth: false
Mon 7/12 12:36:33.633 [VideoFrame-545352504a49@138283] 	clientCanDoMpeg4: true
Mon 7/12 12:36:33.637 [VideoFrame-545352504a49@138283] Supported push containers: [MPEG2-TS, MPEG2-PS, MPEG1-PS]
Mon 7/12 12:36:33.641 [VideoFrame-545352504a49@138283] Checking for whether we are supporting push/pull
Mon 7/12 12:36:33.645 [VideoFrame-545352504a49@138283] 	clientDoesPull: false
Mon 7/12 12:36:33.648 [VideoFrame-545352504a49@138283] 	httpls: false
Mon 7/12 12:36:33.652 [VideoFrame-545352504a49@138283] 	clientDoesMPEG2Push: true
Mon 7/12 12:36:33.655 [VideoFrame-545352504a49@138283] 	clientCanDoMpeg4: true
Mon 7/12 12:36:33.659 [VideoFrame-545352504a49@138283] 	IsNOTLowBandwidth: true
Mon 7/12 12:36:33.663 [VideoFrame-545352504a49@138283] MiniPlayer is using Push mode playback
Mon 7/12 12:36:33.667 [VideoFrame-545352504a49@138283] Looks like it only switches to mpeg4 if it is not a mediaExtender, or low bandwidth....
Mon 7/12 12:36:33.670 [VideoFrame-545352504a49@138283] 	mediaExtender: true
Mon 7/12 12:36:33.673 [VideoFrame-545352504a49@138283] 	lowBandwidth: false
Mon 7/12 12:36:33.677 [VideoFrame-545352504a49@138283] We are a media extender, and we are not low bandwidth....
Mon 7/12 12:36:33.680 [VideoFrame-545352504a49@138283] Supported push containers: [MPEG2-TS, MPEG2-PS, MPEG1-PS]
Mon 7/12 12:36:33.683 [VideoFrame-545352504a49@138283] 	MPEG2_TS containerOK (I think it wants to just remux into MPEG2_TS: true
Mon 7/12 12:36:33.687 [VideoFrame-545352504a49@138283] 	Forcing transcode: false
Mon 7/12 12:36:33.690 [VideoFrame-545352504a49@138283] 	Confirming there is video
Mon 7/12 12:36:33.694 [VideoFrame-545352504a49@138283] 	Checking to see if video it MPEG2
Mon 7/12 12:36:33.697 [VideoFrame-545352504a49@138283] 	Video is not MPEG2 and is a supported codec. Setting video to OK
Mon 7/12 12:36:33.701 [VideoFrame-545352504a49@138283] 	Video codec: H.264
Mon 7/12 12:36:33.705 [VideoFrame-545352504a49@138283] Checking audio codec
Mon 7/12 12:36:33.708 [VideoFrame-545352504a49@138283] 	Has audio
Mon 7/12 12:36:33.711 [VideoFrame-545352504a49@138283] 	Audio code is OK
Mon 7/12 12:36:33.714 [VideoFrame-545352504a49@138283] 	Audio is not low rate
Mon 7/12 12:36:33.717 [VideoFrame-545352504a49@138283] Checking if client can do MPEGHD again....
Mon 7/12 12:36:33.721 [VideoFrame-545352504a49@138283] 	Client can do MPEGHD
Mon 7/12 12:36:33.724 [VideoFrame-545352504a49@138283] MiniPlayer is using the MPEG2 pusher
Mon 7/12 12:36:33.734 [VideoFrame-545352504a49@138283] Mpeg2Reader is detecting timestamp boundaries in the file...
Mon 7/12 12:36:33.738 [VideoFrame-545352504a49@138283] IFrame alignment=true
Mon 7/12 12:36:33.741 [VideoFrame-545352504a49@138283] Mpeg2Reader about to determine the firstPTS in the file...
Mon 7/12 12:36:33.745 [VideoFrame-545352504a49@138283] Mpeg2Reader has found the firstPTS, now determining the duration of the file...
Mon 7/12 12:36:33.754 [VideoFrame-545352504a49@138283] Opened MPEG-2 TS file: F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts firstPTS=324000013 durationMsec=3599583
Mon 7/12 12:36:33.758 [VideoFrame-545352504a49@138283] Mpeg2Reader seeking to pos=0
Mon 7/12 12:36:33.761 [VideoFrame-545352504a49@138283] Setting the transcoder format...
Mon 7/12 12:36:33.765 [VideoFrame-545352504a49@138283] 	There is a current media file...
Mon 7/12 12:36:33.768 [VideoFrame-545352504a49@138283] Not sure exactly what this block is doing.  if the ContainerFormat is not null and serverSideTranscoding, and not use original audio track
Mon 7/12 12:36:33.772 [VideoFrame-545352504a49@138283] Calling openURL0: push: f=MPEG2-TS;dur=313830;br=2884000;[bf=vid;f=H.264;index=0;main=yes;tag=0100;fps=59.94006;fpsn=60000;fpsd=1001;ar=1.777778;arn=16;ard=9;w=1280;h=720;][bf=aud;f=AC3;br=384000;index=1;main=yes;tag=0101;sr=48000;ch=6;][bf=sub;f=SRT;lang=CC1;path=F:\\Sage Recordings\\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt;forced=false;][bf=sub;f=SRT;lang=CC2;path=F:\\Sage Recordings\\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt;forced=false;]
Mon 7/12 12:36:33.775 [VideoFrame-545352504a49@138283] openURL0(push:f=MPEG2-TS;dur=313830;br=2884000;[bf=vid;f=H.264;index=0;main=yes;tag=0100;fps=59.94006;fpsn=60000;fpsd=1001;ar=1.777778;arn=16;ard=9;w=1280;h=720;][bf=aud;f=AC3;br=384000;index=1;main=yes;tag=0101;sr=48000;ch=6;][bf=sub;f=SRT;lang=CC1;path=F:\\Sage Recordings\\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt;forced=false;][bf=sub;f=SRT;lang=CC2;path=F:\\Sage Recordings\\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt;forced=false;])
Mon 7/12 12:36:33.801 [VideoFrame-545352504a49@138283] is ((mediaExtender && pushmode) or hdmediaextend) and not low bandwidth
Mon 7/12 12:36:33.805 [VideoFrame-545352504a49@138283] Setting audio stream for playback to be ID=0x101
Mon 7/12 12:36:34.168 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 751 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:36:34.926 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 1509 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:36:35.683 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 2266 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:36:36.281 [Fork-OPUS4-112742@13e340d] ENDING background recording thumb preloader thread, ID = 0.6833672137190221
Mon 7/12 12:36:36.440 [AWTThreadWatcher-545352504a49@1331810] UILocker=Thread[ActiveRender-545352504a49,2,main]

..... many more hangs .....

Mon 7/12 12:36:59.904 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 26487 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:00.661 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 27244 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:01.420 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 28003 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:02.177 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 28760 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:02.935 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 29518 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:03.693 [AWTThreadWatcher-545352504a49@1331810] EventThread-545352504a49 Hang Detected - hang time = 30275 UILocker=Thread[ActiveRender-545352504a49,2,main]
Mon 7/12 12:37:03.809 [TimeoutHandler@e82c24] TIMEOUT occurred - close the socket asynchronously for java.nio.channels.SocketChannel[connected local=/192.168.1.195:31099 remote=/69.7.56.242:44716]
Mon 7/12 12:37:03.816 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.AsynchronousCloseException
Mon 7/12 12:37:03.826 [MCSRReconnect@17136bf] Preparing the media player for a reload...
Mon 7/12 12:37:03.832 [VideoFrame-545352504a49@138283] Sigma video dim=java.awt.Dimension[width=720,height=480]
Mon 7/12 12:37:03.839 [MCSRReconnect@17136bf] VF.submitJob(VFJob[ReloadPrepareMF r=0.0 t=0 file=null ifn=null])
Mon 7/12 12:37:03.846 [VideoFrame-545352504a49@138283] pausePush0()
Mon 7/12 12:37:03.852 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.ClosedChannelException
Mon 7/12 12:37:03.859 [VideoFrame-545352504a49@138283] setMute0()
Mon 7/12 12:37:03.863 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.ClosedChannelException
Mon 7/12 12:37:03.868 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.ClosedChannelException
Mon 7/12 12:37:03.872 [MiniUIServer@12829f3] MiniUI got connection from java.nio.channels.SocketChannel[connected local=/192.168.1.195:31099 remote=/69.7.56.242:44722]
Mon 7/12 12:37:03.877 [VideoFrame-545352504a49@138283] getDuration : 3599583
Mon 7/12 12:37:03.881 [MiniUIServerConnection@9fdc44] MiniPlayer is adding to its map:545352504a49
Mon 7/12 12:37:03.885 [VideoFrame-545352504a49@138283] VideoFrame.timeSelected2(Fri 7/9 18:00:00.022, true) currFile=MediaFile[id=7508370 A[7339235,7336800,"The Rachel Maddow Show",64241@0709.18:00,60,T] mask=TV host=Media encodedBy=DCT-HDHomeRun Prime Tuner 13112554-0 on 127.0.0.1:9000 MNBCHD format=MPEG2-TS 0:05:13 2884 kbps [#0 Video[H.264 59.94006 fps 1280x720 16:9 progressive id=0100]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=0101]#2 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC1.srt CC1]#3 Subpic[SRT path=F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.CC2.srt CC2]] F:\Sage Recordings\The Rachel Maddow Show - S2021E136 - 7339235-0.ts, Seg0[Fri 7/9 18:00:00.022-Fri 7/9 19:00:00.011]] realDur=3599583
Mon 7/12 12:37:03.889 [VideoFrame-545352504a49@138283] seeking numpushbuffers=0 seekTime=0
Mon 7/12 12:37:03.892 [VideoFrame-545352504a49@138283] Mpeg2Reader seeking to pos=0
Mon 7/12 12:37:03.896 [VideoFrame-545352504a49@138283] flushPush0()
Mon 7/12 12:37:03.899 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.ClosedChannelException
Mon 7/12 12:37:03.903 [VideoFrame-545352504a49@138283] Creating new push thread
Mon 7/12 12:37:03.910 [VideoFrame-545352504a49@138283] Channel Change Time=1626118623910 NOTE: Not valid if this was not a direct channel change!
Mon 7/12 12:37:03.914 [Pusher@1986999] Pusher thread is starting
Mon 7/12 12:37:03.919 [Pusher@1986999] Miniplayer pusher using buffer size of 32768
Mon 7/12 12:37:03.922 [VideoFrame-545352504a49@138283] VF processing job VFJob[ReloadPrepareMF r=0.0 t=0 file=null ifn=null] nPlayin=true
Mon 7/12 12:37:03.926 [VideoFrame-545352504a49@138283] VF processing on UI Thread VFJob[ReloadPrepareMF r=0.0 t=0 file=null ifn=null]
Mon 7/12 12:37:03.930 [ActiveRender-545352504a49@1b85cc1] VideoFrame got registration of a subtitle UI component: sage.ZCCLabel[loc=java.awt.Point[x=288,y=820] size=java.awt.Dimension[width=1344,height=216]]
Mon 7/12 12:37:03.934 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 284 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:03.938 [ActiveRender-545352504a49@1b85cc1] VideoFrame got registration of a cc UI component: sage.ZCCLabel[loc=java.awt.Point[x=192,y=108] size=java.awt.Dimension[width=1536,height=864]]
Mon 7/12 12:37:03.942 [VideoFrame-545352504a49@138283] stopPush0()
Mon 7/12 12:37:03.946 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:03.950 [VideoFrame-545352504a49@138283] Error with MiniPlayer, closing UI: java.nio.channels.ClosedChannelException
Mon 7/12 12:37:03.954 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 285 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:03.959 [VideoFrame-545352504a49@138283] Closing down MiniPlayer
Mon 7/12 12:37:03.963 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 384 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:03.967 [ReProcessHook@1a26deb] Start looking for max channel digits
Mon 7/12 12:37:03.971 [VideoFrame-545352504a49@138283] closeDriver0()
Mon 7/12 12:37:03.974 [ReProcessHook@1a26deb] New max channel = 4, from channel 3291 on lineup 'Comcast King County South - Digital - Seattle (sdepg)'
Mon 7/12 12:37:03.978 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:03.982 [MCSRReconnect@17136bf] MediaPlayer is ready for the reload.
Mon 7/12 12:37:03.986 [VideoFrame-545352504a49@138283] VF processing job null nPlayin=false
Mon 7/12 12:37:03.990 [MCSRReconnect@17136bf] MCSR reconnect daemon has started...wait up to 30 seconds for a client reconnect...
Mon 7/12 12:37:03.993 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 385 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:03.997 [VideoFrame-545352504a49@138283] isRec=false rd=3599989 base=0 eos=false
Mon 7/12 12:37:04.002 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 467 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:04.005 [ReProcessHook@1a26deb] Done looking for max channel digits; elapsed time: 33
Mon 7/12 12:37:04.009 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:04.013 [VideoFrame-545352504a49@138283] VF thread is now waiting for 0:00:00.000
Mon 7/12 12:37:04.016 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 468 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:04.019 [Fork-JREkiwi-615771@2f6355] Starting Comskip Playback v2.1.3 Thread: Thread[Fork-JREkiwi-615771,5,main], for UI context 545352504a49
Mon 7/12 12:37:04.023 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 695 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:04.026 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:04.030 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 696 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 4
Mon 7/12 12:37:04.035 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1146 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:04.038 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:04.042 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1147 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:04.045 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1152 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:04.049 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:04.052 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1153 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:04.055 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1178 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:04.058 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found:  error=java.lang.NumberFormatException: For input string: ""
Mon 7/12 12:37:04.062 [SRTSubtitleMonitor@9fdc44] ERROR in SRT file; didn't find timecode on line; instead found: 1179 error=java.lang.StringIndexOutOfBoundsException: String index out of range: 5
Mon 7/12 12:37:11.304 [Timer-0@1db2997] CD: MonitorClient: Looking for work.

[ojones]

Josh,

I am running your format parser and my source is a cable card stream so I may have subtitles present (but don't use them...).

I did run a few tests this afternoon where I spun up a 2nd subnet off of my router (gotta love PfSense) and intentionally degraded the link speed to 10mb/s. I put an nvidia shield in this new subnet (wired; brought the same unit home that I was testing previously) and then connected the 1.8.1 client through a loopback via my WAN FQDN. Streaming worked without errors - this is a slower connection than I was having errors on last week. The only other difference is that the latency on that link was 75ms and higher (sometimes much higher) vs <1ms inside my lab.

Is there anything I could do to help trouble shoot this? I am trying to duplicate the error now but no luck yet in a lab situation.

[ojones]

Bandwidth test question (in two parts):

First: IF the bandwidth test determines the connection speed is less than the forced encoding speed what should happen?

Second: Is the bandwidth speed based on upload or download bandwidth? I strung my nvidia shield off a 4g wifi hotspot that was able to speed test @ 50mb/s down and 20mb/s upload. I was able to duplicate the hang using this setup reliably. The bandwidth test in the Sage logs reads 6-7mbps.

[hb4]

Originally Posted by ojones

Bandwidth test question (in two parts):

First: IF the bandwidth test determines the connection speed is less than the forced encoding speed what should happen?

Second: Is the bandwidth speed based on upload or download bandwidth? I strung my nvidia shield off a 4g wifi hotspot that was able to speed test @ 50mb/s down and 20mb/s upload. I was able to duplicate the hang using this setup reliably. The bandwidth test in the Sage logs reads 6-7mbps.

FS4K has been working great for me up until about 3 weeks ago. This is with never more than 20mbs download speed at the remote location and 11-12mbs upload speed at the server. Latency is reported at 13ms by 'Fast'.

Edit:> I just logged in remotely to the server pc and did a tracert to my remote location. The third hop was to comcast and reported 334ms round trip time. The last hop, which was the demarc of the ISP serving this remote location, was 51,11, and 12ms - whatever that means.

[ojones]

I am going to try to side-load 1.8.0 tomorrow and retest via a 4g connection.

I couldn't replicate in a lab setting. Anyone else able to test 1.8.1 over a wan link with latency?

[hb4]

Originally Posted by ojones

I am going to try to side-load 1.8.0 tomorrow and retest via a 4g connection.

I couldn't replicate in a lab setting. Anyone else able to test 1.8.1 over a wan link with latency?

I am using the miniclient over a wan with the latency I reported earlier. It mostly hangs, but sometimes plays a recording. I've posted a log as well. I'm happy to do more testing, but need some specific direction since I have no experience with troubleshooting a WAN connection nor interpreting the sagetv.txt logs.

My current plan is to go back to the previous jar and see if that works.

[ojones]

HB4 & Josh,

I found some time to downgrade the miniclient on my shield from 1.8.1 to 1.8.0.

Verdict so far is 1.8.0 is streaming well over a Verizon 4g connection with no crashes at 2mb/s and 4mb/s forced streaming speed.

This reliably crashed running 1.8.1 over the same 4g hotspot yesterday. Both 1.8.1 and 1.8.0 run perfectly on the same lan/subnet and are perfectly happy running across subnets in my lab (even if I degrade the link speed to 10 Mbps although that stutters it didn't cause the crash we've duplicated on higher latency links).

LMK what i can from a trouble shooting front to work on this further. I have shields running 1.8.1 and 1.8.0 and happy to play around.

[Zogg]

So if I try to use the Miniclient on my phone from the Internet, I get a message saying that No Place Shifter users are available. But if I activate my VPN then it works fine.

I don't remember having this issue with my old server, but it has been this way since I moved to Unraid. And maybe I had a Place Shifter user set up but I don't remember doing it.

Can someone tell me how it's supposed to work?

[hb4]

Originally Posted by ojones

HB4 & Josh,

I found some time to downgrade the miniclient on my shield from 1.8.1 to 1.8.0.

Verdict so far is 1.8.0 is streaming well over a Verizon 4g connection with no crashes at 2mb/s and 4mb/s forced streaming speed.

I sideloaded v1.8.0 today and after a sample playback of 1, it worked. I had to uninstall v1.8.1 to get 1.8/0 to install. Obvious, now that I think about it. I'll report back after some more attempts.

[nyplayer]

Originally Posted by Zogg

So if I try to use the Miniclient on my phone from the Internet, I get a message saying that No Place Shifter users are available. But if I activate my VPN then it works fine.

I don't remember having this issue with my old server, but it has been this way since I moved to Unraid. And maybe I had a Place Shifter user set up but I don't remember doing it.

Can someone tell me how it's supposed to work?

You need to add users. Or else anyone could get into your server if a user was not required.