HD200 playback simply stops randomly

[pciccone]

I have a new CentOS 5 based SageTV insallation with the strangest problem. When playback starts from any recorded or live TV source (SD or HD) it will simply stop and return to the main menu by itself with no error after a random period of time. It seems that if the HD200 is HARD power cycled the frequency goes down but eventually after an hours playback start to get progressivly worse to the point it happens after 30 seconds or so.

Also most likely relating to the same issue sometimes playback will skip backwards or forwards by itself (with the menu bar appearing) almost like you hit the buttons on the remote to skip either direction, or we may go into groundhog mode where a segment starts looping all by itself even if you start and stop, or go to another program it will start looping.

When these problems are not occuring playback and menu movement is flawless, including HD playback. Environment is HDHomeRun tuners with a rooftop antenna. HD200 firmware and Sage STV are at the latest versions avaialble when checking via "check for update". Issue will occur with content either recorded by SageTV or external imported content (including AVI vs MPG)

Below is one sample debug that shows the stop of playback, but I cannot find anything obvious. I also noticed that in some situations a "Parser lockup" would appear in the native.log at the exact moment playback stops but this is not always the case.

Sat 5/1 10:35:54.094 [Pusher@fea539] Miniplayer pusher using buffer size of 131072
Sat 5/1 10:35:54.104 [Pusher@fea539] Adjusting peek buffer size to: 131072
Sat 5/1 10:35:54.104 [ReProcessHook@8edb84] ===== List Creation Elapsed Time = [10]
Sat 5/1 10:35:54.104 [ReProcessHook@8edb84] Category Filter Elapsed Time = [0]
Sat 5/1 10:35:54.104 [ReProcessHook@8edb84] Other Filter Elapsed Time = [0]
Sat 5/1 10:35:54.104 [ReProcessHook@8edb84] No duplicates Elapsed Time = [0]
Sat 5/1 10:35:54.107 [ReProcessHook@8edb84] Sorting Elapsed Time = [3]
Sat 5/1 10:35:54.108 [ReProcessHook@8edb84] Grouping Elapsed Time = [0]
Sat 5/1 10:35:54.108 [ReProcessHook@8edb84] ===== Overall Group Creation Elapsed Time = [14]
Sat 5/1 10:35:54.139 [Pusher@fea539] Seek target=2120 actual=2120 diff=0
Sat 5/1 10:35:54.168 [ReProcessHook@edf1de] Start looking for max channel digits
Sat 5/1 10:35:54.169 [ReProcessHook@edf1de] New max channel = 3, from channel 16-1 on lineup 'Atlanta - Digital Broadcast'
Sat 5/1 10:35:54.170 [ReProcessHook@edf1de] New max channel = 4, from channel 32-10 on lineup 'Atlanta - Digital Broadcast'
Sat 5/1 10:35:54.174 [ReProcessHook@edf1de] Done looking for max channel digits; elapsed time: 6
Sat 5/1 10:35:54.182 [ActiveRender-001d6a5ca8d6@a06816] VideoFrame got registration of a subtitle UI component: sage.q[loc=java.awt.Point[x=144,y=410] size=java.awt.Dimension[width=672,height=108]]
Sat 5/1 10:35:54.182 [ActiveRender-001d6a5ca8d6@a06816] VideoFrame got registration of a cc UI component: sage.q[loc=java.awt.Point[x=96,y=54] size=java.awt.Dimension[width=768,height=432]]
Sat 5/1 10:35:54.242 [Pusher@fea539] playPush0()
 
<watched 28 seconds of TV here>
 
Sat 5/1 10:36:22.890 [EventRouter-001d6a5ca8d6@b5615d] VF.submitJob(VFJob[CloseMF r=0.0 t=0 file=null ifn=null])
Sat 5/1 10:36:22.891 [VideoFrame-001d6a5ca8d6@104a4b6] VF processing job VFJob[CloseMF r=0.0 t=0 file=null ifn=null] nPlayin=true
Sat 5/1 10:36:22.891 [VideoFrame-001d6a5ca8d6@104a4b6] VF processing on UI Thread VFJob[CloseMF r=0.0 t=0 file=null ifn=null]
Sat 5/1 10:36:23.060 [VideoFrame-001d6a5ca8d6@104a4b6] Updated:Watched[id=165823 Airing=A[147888,147506,"Daddy Day Camp",32795@0412.01:00,120], WatchStart=Mon 4/12 1:00:00.005, WatchEnd=Mon 4/12 1:35:48.835, RealStart=Mon 4/12 23:01:12.810, RealEnd=Sat 5/1 10:36:22.892]
Sat 5/1 10:36:23.061 [VideoFrame-001d6a5ca8d6@104a4b6] VF logFileWatch doneAir=A[147888,147506,"Daddy Day Camp",32795@0412.01:00,120] theTime=Mon 4/12 1:35:48.835 recTime=Mon 4/12 1:00:00.005
Sat 5/1 10:36:23.062 [VideoFrame-001d6a5ca8d6@104a4b6] stopPush0()
Sat 5/1 10:36:23.090 [VideoFrame-001d6a5ca8d6@104a4b6] Closing down MiniPlayer
Sat 5/1 10:36:23.090 [VideoFrame-001d6a5ca8d6@104a4b6] closeDriver0()
Sat 5/1 10:36:23.091 [VideoFrame-001d6a5ca8d6@104a4b6] VF processing job null nPlayin=false
Sat 5/1 10:36:23.091 [EventRouter-001d6a5ca8d6@b5615d] Seeker.finishWatch(UIManager:localhost@@001d6a5ca8d6-1bb6a69)
Sat 5/1 10:36:23.091 [VideoFrame-001d6a5ca8d6@104a4b6] VF thread is now waiting for 0:00:

Appreciate your time in reviewing this thread. I tried as many search terms I can think of and can't seem to find this problem documented anywhere.

[drewg]

Originally Posted by pciccone

I have a new CentOS 5 based SageTV insallation with the strangest problem

32- or 64-bits? What java version are you using? Are you using the Sun 1.6 32-bit java?

Drew

[pciccone]

64-bit, and modified startsage to point to a specific version:

startsage:
PATH=/usr/java/jre1.6.0_19/bin:$PATH
export PATH

[root@omega server]# ls -l /usr/java
total 4
lrwxrwxrwx 1 root root 16 Apr 9 19:31 default -> /usr/java/latest
drwxr-xr-x 7 root root 4096 Apr 9 19:31 jre1.6.0_19
lrwxrwxrwx 1 root root 21 Apr 9 19:31 latest -> /usr/java/jre1.6.0_19

I dont remember now, but I think I install this RPM jre-6u19-linux-i586.rpm manually as I have it still sitting in my src directory....

[root@omega ~]# java -version
java version "1.6.0"
OpenJDK Runtime Environment (build 1.6.0-b09)
OpenJDK 64-Bit Server VM (build 1.6.0-b09, mixed mode)

[drewg]

Originally Posted by pciccone

PATH=/usr/java/jre1.6.0_19/bin:$PATH
export PATH

OK, that looks good.

Did you enable debug logging on the server? (stopsage; edit Sage.properties and change debug_logging=false to debug_logging=TRUE; startsage). Maybe the log messages will be more helpful if it is enabled.

Have you used the HD200 before, or is it brand new? Does it exhibit problems if you share your media via SMB and play it in standalone mode on the HD200?

Drew

[pciccone]

The log output above was actually with debug already enabled. With it off the only info it would have showed is when the thumbnails were loaded.

The HD200 is not new, and I never recalled this on the previous Windows install. I will try grabbing some media directly and see what it does.

More to come....

[drewg]

Originally Posted by pciccone

The log output above was actually with debug already enabled. With it off the only info it would have showed is when the thumbnails were loaded.

The HD200 is not new, and I never recalled this on the previous Windows install. I will try grabbing some media directly and see what it does.

More to come....

It probably works then, so this might not be informative.

I'm just making wild guesses at this point, but what is your java heap size? Have you tried to double it to 512MB?

Is the network reliable?

Drew

[pciccone]

To my knowledge the network should be reliable, I can hook-up a laptop later and I will run pings from that location to ensure. I increased the heap size to 512mb (-Xmx) and restarted the server.

Tied up with work now, will try to test the results later.