2016-01-13, 09:48 PM
After moving to a new place that actually has OTA reception, I started playing around with the HDHomeRun setup I used way back when in college. After many hours of setup, I thought I had everything working. I was able to get schedule information synced every day, I had commercial detection tagging all my recordings, life was wonderful. Being an old man, I was more or less only recording Jeopardy. My roommate then tried recording something and had a weird problem. He recorded a program on a different station, and shortly after starting, the screen froze and he was back in the recording menu with a prompt asking if he wanted to delete his finished recording. I quickly discovered that there was a commercial detected at the start of the program. If I removed the commercial tags, the recording would play just fine. However, if I attempted to skip around the recording at all, I got a frozen screen for about 10 seconds, and then eventually was booted back to the recording menu with the end of video prompt. As a sanity test I opened the raw file in a few other video players (vlc/mpc) and the video worked just fine. My guess is that there's just enough corruption that nPVR can't build a seek index, but my other video players are smart enough to just deal with it. I use ffdshow to decode both the sound and audio, and to confirm that the problem wasn't there I tried alternating disabling the video and audio decoders. In both tests, the playback would end as soon as I did any skip. As a further test, I tried recording a few other short bits from the "bad" station. I could skip just fine in these tests. Im guessing that the actual recording was just long enough to pick up enough corruption to break everything.
I finally started looking through the npvr.log hoping to find anything. This is what I saw when I made a skip in the "corrupted file"
Nothing here is alerting me to any problems. As a control, I wanted to see what events were logged when I skip in a functional recording
Everything looks mostly the same for 35 lines, but the corrupt recording has a 30 second gap before returning an eventcode of 0x0003 and 0x0001 which means nothing to me. At this point I'm out of ideas. Does anyone have any ideas how I can fix this problem, or at least better track down where the problem is?
Thanks
I finally started looking through the npvr.log hoping to find anything. This is what I saw when I made a skip in the "corrupted file"
Code:
2016-01-13 13:42:31.447 [DEBUG][1] User is trying to skip.
2016-01-13 13:42:31.447 [DEBUG][1] Current position is: 15.583833694458
2016-01-13 13:42:31.447 [DEBUG][1] Asking for position: 75.5838317871094
2016-01-13 13:42:31.448 [DEBUG][1] Pause()
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition(75.583832)
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap2
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap3
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap4
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap5
2016-01-13 13:42:31.460 [DEBUG][1] Using timing.info, jumping to time 75.583832 (offset 124178888)
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap6
2016-01-13 13:42:31.460 [DEBUG][1] SetPosition@skipmap7
2016-01-13 13:42:31.512 [DEBUG][1] after skip disk offset 124216488
2016-01-13 13:42:31.512 [DEBUG][1] SetPosition@exit
2016-01-13 13:42:31.515 [DEBUG][1] Play()
2016-01-13 13:42:31.515 [DEBUG][1] skippedWhilePaused enabled (position: 75.5838317871094)
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition(75.783829)
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap2
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap3
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap4
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap5
2016-01-13 13:42:31.515 [DEBUG][1] Using timing.info, jumping to time 75.783829 (offset 124178888)
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap6
2016-01-13 13:42:31.515 [DEBUG][1] SetPosition@skipmap7
2016-01-13 13:42:31.517 [DEBUG][1] after skip disk offset 124291688
2016-01-13 13:42:31.517 [DEBUG][1] SetPosition@exit
2016-01-13 13:42:31.517 [DEBUG][1] After skipping position reports as: 75.7838287353516
2016-01-13 13:42:31.517 [DEBUG][1] GetEventCode() returned: 0x000e
2016-01-13 13:42:31.541 [DEBUG][1] Updating OSD.
2016-01-13 13:42:31.844 [DEBUG][1] Updating OSD.
2016-01-13 13:42:32.826 [DEBUG][1] Updating OSD.
2016-01-13 13:42:33.804 [DEBUG][1] Updating OSD.
2016-01-13 13:42:34.817 [DEBUG][1] Updating OSD.
2016-01-13 13:42:35.545 [DEBUG][1] Hiding OSD.
2016-01-13 13:43:13.442 [DEBUG][1] GetEventCode() returned: 0x0003
2016-01-13 13:43:13.442 [DEBUG][1] GetEventCode() returned: 0x0001
2016-01-13 13:43:13.442 [DEBUG][1] About to store playback position information
2016-01-13 13:43:13.442 [DEBUG][1] PlaybackPositionHelper.StorePlaybackPosition(Galavant_20160110_20002101.ts, 3778, 3778)
2016-01-13 13:43:13.442 [DEBUG][1] PlaybackPositionHelper.DeletePlaybackPosition(C:\Temp\Galavant\Galavant_20160110_20002101.ts)
2016-01-13 13:43:13.777 [DEBUG][1] Stop@0
2016-01-13 13:43:13.778 [DEBUG][1] Stopping graph@1
2016-01-13 13:43:13.784 [DEBUG][1] Stopping graph@2
2016-01-13 13:43:13.788 [DEBUG][1] Stopping graph@3
2016-01-13 13:43:13.788 [DEBUG][1] CAllocator::Release (m_refCount=3)
2016-01-13 13:43:13.788 [DEBUG][1] Removing filter NPVR CC Dump
2016-01-13 13:43:13.789 [DEBUG][1] Removing filter Video Mixing Renderer 9
2016-01-13 13:43:13.790 [DEBUG][1] CAllocator::Release (m_refCount=2)
2016-01-13 13:43:13.790 [DEBUG][1] CAllocator::Release (m_refCount=1)
2016-01-13 13:43:13.790 [DEBUG][1] CAllocator::Release (m_refCount=0)
2016-01-13 13:43:13.790 [DEBUG][1] CAllocator::Release() deleting instance
2016-01-13 13:43:13.816 [DEBUG][1] Removing filter NPVR PES Collector (Teletext)
2016-01-13 13:43:13.816 [DEBUG][1] Removing filter NPVR PES Collector (DVBSubs)
2016-01-13 13:43:13.816 [DEBUG][1] Removing filter AC3 Audio Renderer
2016-01-13 13:43:13.817 [DEBUG][1] Removing filter Line 21 Decoder
2016-01-13 13:43:13.817 [DEBUG][1] Removing filter ffdshow Video Decoder
2016-01-13 13:43:13.823 [DEBUG][1] Removing filter ffdshow Audio Decoder
2016-01-13 13:43:13.829 [DEBUG][1] Removing filter NPVR CC Extractor
2016-01-13 13:43:13.829 [DEBUG][1] Removing filter MPEG-2 Demultiplexer
2016-01-13 13:43:13.829 [DEBUG][1] Removing filter NPVR TS Reader2
2016-01-13 13:43:13.831 [DEBUG][1] PlaybackPositionHelper.GetPlaybackPosition(C:\Temp\Galavant\Galavant_20160110_20002101.ts)
2016-01-13 13:43:13.850 [DEBUG][1] play to completion
Nothing here is alerting me to any problems. As a control, I wanted to see what events were logged when I skip in a functional recording
Code:
2016-01-13 13:45:28.211 [DEBUG][1] User is trying to skip.
2016-01-13 13:45:28.211 [DEBUG][1] Current position is: 43.2552070617676
2016-01-13 13:45:28.211 [DEBUG][1] Asking for position: 103.25520324707
2016-01-13 13:45:28.211 [DEBUG][1] Pause()
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition(103.255203)
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap2
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap3
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap4
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap5
2016-01-13 13:45:28.232 [DEBUG][1] Using timing.info, jumping to time 103.255203 (offset 147740176)
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap6
2016-01-13 13:45:28.232 [DEBUG][1] SetPosition@skipmap7
2016-01-13 13:45:28.279 [DEBUG][1] after skip disk offset 147777776
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@exit
2016-01-13 13:45:28.279 [DEBUG][1] Play()
2016-01-13 13:45:28.279 [DEBUG][1] skippedWhilePaused enabled (position: 103.25520324707)
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition(103.455200)
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@skipmap
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@skipmap2
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@skipmap3
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@skipmap4
2016-01-13 13:45:28.279 [DEBUG][1] SetPosition@skipmap5
2016-01-13 13:45:28.280 [DEBUG][1] Using timing.info, jumping to time 103.455200 (offset 147740176)
2016-01-13 13:45:28.280 [DEBUG][1] SetPosition@skipmap6
2016-01-13 13:45:28.280 [DEBUG][1] SetPosition@skipmap7
2016-01-13 13:45:28.280 [DEBUG][1] after skip disk offset 147852976
2016-01-13 13:45:28.281 [DEBUG][1] SetPosition@exit
2016-01-13 13:45:28.281 [DEBUG][1] After skipping position reports as: 103.455200195313
2016-01-13 13:45:28.281 [DEBUG][1] GetEventCode() returned: 0x000e
2016-01-13 13:45:28.306 [DEBUG][1] Updating OSD.
2016-01-13 13:45:28.933 [DEBUG][1] Updating OSD.
2016-01-13 13:45:30.022 [DEBUG][1] Updating OSD.
2016-01-13 13:45:31.011 [DEBUG][1] Updating OSD.
2016-01-13 13:45:31.980 [DEBUG][1] Updating OSD.
Everything looks mostly the same for 35 lines, but the corrupt recording has a 30 second gap before returning an eventcode of 0x0003 and 0x0001 which means nothing to me. At this point I'm out of ideas. Does anyone have any ideas how I can fix this problem, or at least better track down where the problem is?
Thanks