Modify
Warning Please read the Ticket HowTo before creating or commenting on a ticket. Failure to do so may cause your ticket to be rejected or result in a slower response.

Opened 14 months ago

Closed 10 months ago

Last modified 10 months ago

#11435 closed Bug Report - General (fixed)

recordedseek as recorded differs from mythcommflag

Reported by: blm-ubunet@… Owned by: jpoet
Priority: minor Milestone: 0.27
Component: MythTV - Recording Version: Master Head
Severity: low Keywords: H264 recordedseek
Cc: Ticket locked: no

Description

V dirty 0.26+fixes patched with all recent H264 related commits.
The latest H264 commits (latest month) have resulted in very slow playback seeking & odd cut-list editor behaviour; looks to be playing sequences of frames for each keyframe.

mythcommflag --rebuild fixes seek "slowness" & cut-list editor problem.

The mythcommflag rebuild seektable is very different to "as recorded"

Attachments (19)

seektable-rebuildmythcommflag.txt (166.7 KB) - added by anonymous 14 months ago.
seektable-recorded.txt (166.9 KB) - added by blm-ubunet@… 14 months ago.
seektable created as recorded..
ffprobe-rearranged.txt (1.0 KB) - added by blm-ubunet@… 14 months ago.
ffprobe of recording, sorted in spreadsheet etc
seekdump2.csv (21.2 KB) - added by blm-ubunet@… 14 months ago.
ffprobe output in csv format
InaccurateSeek.patch (654 bytes) - added by jpoet 14 months ago.
version.txt (805 bytes) - added by blm-ubunet@… 14 months ago.
Potentially misleading mythfrontend --version info
diff-H264Parser.cpp.txt (14.6 KB) - added by blm-ubunet@… 13 months ago.
diff patch against git master (1 week ago) H264Parser.cpp
diff-H264Parser.h.txt (2.7 KB) - added by blm-ubunet@… 13 months ago.
diff patch against git master (1 week ago) H264Parser.h
diff-dtvrecorder.cpp.txt (7.4 KB) - added by blm-ubunet@… 13 months ago.
diff patch against git master (1 week ago) dtvrecorder.cpp
git-diff.txt (20.7 KB) - added by blm-ubunet@… 13 months ago.
git diff against master branch
git_diff.txt (21.2 KB) - added by blm-ubunet@… 13 months ago.
fresh git diff to master with non-video stream unblocked.
git_diff.2.txt (21.3 KB) - added by blm-ubunet@… 13 months ago.
git diff to master..fix for warpme problem recording
git_diff3.txt (23.8 KB) - added by blm-ubunet@… 12 months ago.
git diff to master ; added some mpeg2 video changes etc
git-diff4-cleaned.txt (24.3 KB) - added by blm-ubunet@… 12 months ago.
git diff to master. Rearranged reset of _seen_sps so that only occurs with payload start & is similar to PES_sync.
SPS-H264Parser.patch (17.1 KB) - added by jpoet 11 months ago.
Fix parsing of SEI_TYPE_RECOVERY_POINT
SPS-H264Parser-0.26.patch (22.1 KB) - added by jpoet 11 months ago.
fixes/0.26 version
gitdiff-cleaned5.txt (25.0 KB) - added by blm-ubunet@… 11 months ago.
allow for H264 stream without SPS but still use it if possible.
keyframe-buffer-0.26.patch (1.3 KB) - added by jpoet 10 months ago.
Flush payload buffer at start each new payload - 0.26 version
keyframe-buffer.patch (1.3 KB) - added by jpoet 10 months ago.
Flush payload buffer whenever a new payload starts

Download all attachments as: .zip

Change History (63)

Changed 14 months ago by anonymous

Changed 14 months ago by blm-ubunet@…

seektable created as recorded..

comment:1 Changed 14 months ago by stichnot

  • Status changed from new to infoneeded_new
  • Version changed from Master Head to 0.26-fixes

I have a suspicion that "garbage" frames at the beginning of the recording are being parsed and processed by the recorder but ignored by the player/ffmpeg until the first keyframe is seen.

Could you attach the seektable for such a recording, before and after running "mythcommflag --rebuild"?

select * from recordedseek where chanid=<my_chanid> and starttime=<my_starttime>
order by mark, type;

This may be a dup of #11328.

Changed 14 months ago by blm-ubunet@…

ffprobe of recording, sorted in spreadsheet etc

comment:2 Changed 14 months ago by blm-ubunet@…

The prev attached files were made with "select * from recordedseek where type in (33,9) and chanid=1003 and starttime=20130303020100 order by mark;"

Your cmd shows nothing diff/new at beginning of the same recording after running mythcommflag.

I have added some processed ffprobe info from the very start of the same recording.
(real ffmpeg git 15 Feb 2013).

The recorded seek entry does not point at any ffprobe packet offset.
mythcommflag gets one pkt offset match at coded_pict 24.

comment:3 Changed 14 months ago by stichnot

Sorry, I didn't notice that you had already attached the seektables.

Could you make the first ~50MB of the recording available for download and analysis? (Or any such problematic recording, along with the corresponding seektable produced by the recorder.)

comment:4 Changed 14 months ago by blm-ubunet@…

All my recordings have similar issue (worse with HD ones).
Slow seeking is like using a IR remote c.f. keyboard.

Using older kernel but with recent build of v4l-dvb.

ffprobe finds one extra keyframe at beginning & has this error parsing file:
"[mpegts @ 0x27d86e0] PES packet size mismatch"

packet,video,0,11174706245,124163.402722,11174688245,124163.202722,1800,0.020000,N/A,N/A,129815,376,K
packet,video,0,11174792645,124164.362722,11174774645,124164.162722,1800,0.020000,N/A,N/A,114004,1232340,K
packet,video,0,11174879045,124165.322722,11174861045,124165.122722,1800,0.020000,N/A,N/A,114868,2533112,K
packet,video,0,11175008645,124166.762722,11174990645,124166.562722,1800,0.020000,N/A,N/A,101747,4627620,K
packet,video,0,11175095045,124167.722722,11175077045,124167.522722,1800,0.020000,N/A,N/A,122790,5889100,K

Changed 14 months ago by blm-ubunet@…

ffprobe output in csv format

comment:5 Changed 14 months ago by blm-ubunet@…

link to sample first 50MB
http://d01.megashares.com/dl/7P3CVS7/part1.mpg

Cut from recording with:
dd if=1003_20130303020100.mpg of=part1.mpg bs=1024 count=50000

comment:6 Changed 14 months ago by jpoet

Just to be clear, you are running 0.26 fixes 3944ca9a ? What is your source? BBC?

Personally, to get acceptable seeks performance with HD-PVR material I have to effectively turn "accurate" seeking off as illustrated with the attached patch.

Changed 14 months ago by jpoet

comment:7 Changed 14 months ago by blm-ubunet@…

0.26+fixes + (manually) patched with every H264/dvb related commit from master..
(Mr Stichnot has been busy).

Source is dvb-t H264 1080i50 & 576i50 and a range of datarates..

Seeking (playback) is okay/usable after seektable rebuild, not as lightening fast as couple months ago..
Seeking (cutlist ed) is very good after seektable rebuild.
Haven't checked the (key)frame cutting accuracy yet..

The sample HD-PVR recordings that I have (sourced from around here), play okay/fine after cleaning up the beginning. Recent commits should have fixed the beginnings.
Processing with ffmpeg requires extended "-analyzeduration" period.

Thanks for the interest & the patch..

comment:8 Changed 14 months ago by stichnot

To reiterate jpoet's question, please attach the output of "mythfrontend --version". If it's possible for you to enumerate the set of commits from Master that you have cherry-picked, that would also be helpful. We would especially like to know if you have all the commits related to #11328.

comment:9 Changed 14 months ago by blm-ubunet@…

Version:
Don't place to much weight by version.txt attachment.

Commits:
Any & every commit with your name from Dec last..
Definitely commits around/related 11328.

There is no list of commits used. I only have a couple of private code mods, if myth breaks I give up & start again.
git diff against 0.26+fixes (3 Jan 2013) is 382K..

Another (cosmetic?) observation:
The repeated execution of mythcommflag --rebuild causes the "progress" percentage display to go 20,000%.
First time is okay (100%)..maybe I missed that code commit..

Jpoet:
Tried with "kInaccuracyDefault = 0.2;"; bit faster maybe, but --rebuild seektable still wins..

This is a minor issue & I thought the slow seeking problem would be common but if you guys have matching seektables for H264 recordings & mythcommflag --rebuild, I'll live with slow seeking, it is still better than all other players.

Changed 14 months ago by blm-ubunet@…

Potentially misleading mythfrontend --version info

comment:10 Changed 14 months ago by blm-ubunet@…

Forget about "fixing" this ticket, please just close it invalid..

I only ask you to do one thing:
check your recorded seektable against mythcommflag --rebuild for your H264 recordings.

comment:11 Changed 14 months ago by stichnot

  • Owner changed from danielk to stichnot

I appreciate your efforts in tracking and evaluating this issue.

At your request, I'll close the ticket, as it's clearly going to be very tough to reproduce and validate your setup.

Currently in Master, in my tests of various HD-PVR and HDHR recordings, the keyframe numbers, file positions, and timestamps are pretty much exact matches, except for occasional keyframe entries that are missing from either the recorder or mythcommflag.

If you find a chance to try out Master, I would appreciate hearing whether the same holds for your recordings.

comment:12 Changed 14 months ago by stichnot

  • Resolution set to Works for me
  • Status changed from infoneeded_new to closed

comment:13 Changed 13 months ago by blm-ubunet@…

HD-PVR etc are all old-school IDR H264..

The root cause of the problem is a bug in H264Parser.cpp when detecting "keyframe" in AVC.

The meat of the change is this line 1065..

au_contains_keyframe_message = (recovery_frame_cnt >= 0);

I'm still not (yet) getting exact agreement with ffprobe (very close) but there are no completely wrong values as before & seeking is better.
The exact definition of "keyframe offset" w.r.t AVC sliced refresh is unclear (to me).

comment:14 Changed 13 months ago by blm-ubunet@…

After attempting to study this:
http://www.itu.int/rec/T-REC-H.264-201201-I/en
and reference H264 decoder:
http://iphome.hhi.de/suehring/tml/
I went thru' H264Parser line by line trying to align to spec & reference decoder when I got lost..

I think the premise that the recording starts on keyframe is wrong, that first GOP is not decode-able without SPS/PPS.
Had to make changes to dtvrecorder.cpp to sync to SPS. A small change to mpeg2 code was required because of common code (with H264).
H264Parser signals (outputs) I-frame or sliced refresh AVC.

I can not test H264 I-frame or mpeg2 video recording.

Tested with H264-AVC OTA broadcast & playback using VDPAU & OpenGL.
As the H264Parser is reused by avformatdecoder, I checked that HD-PVR & HDHR samples play okay. My HD-PVR samples include 11159 (60p) & 50p..

Playback seeking is very good & cutlist editor faultless.

I don't think recording sync to SPS is the perfect solution but it is better than sync to keyframe/AU.
My coding style is naive/simple & there are a few unused variables.

A git diff to master is possble in a week or so but for now diff files only..
Thanks for your help..

ps: ignore the previous comment about "au_contains_keyframe_message" being wrong..

Changed 13 months ago by blm-ubunet@…

diff patch against git master (1 week ago) H264Parser.cpp

Changed 13 months ago by blm-ubunet@…

diff patch against git master (1 week ago) H264Parser.h

Changed 13 months ago by blm-ubunet@…

diff patch against git master (1 week ago) dtvrecorder.cpp

comment:15 Changed 13 months ago by warpme@…

Just FYI: I just want to confirm v.good results with blm-ubunet patches. By curiosity I back-ported them to 0-26-fixes, and for me so far they are 100% success. So: I don't have issues with seek table discrepancy in recorder vs commflag --rebuild (#11470); so far (after 1 day of tests) all seems to be working OK (H.264/MPEG2 LiveTV, movies); LiveTV channel switches are almost fast as fastest I had (fastest are without http://code.mythtv.org/cgit/mythtv/commit/?id=e54b9b6fd635df024f81c1d2f33956996c95c379); playback seeking & cutlist editor are also seems to be fastest & without negative effects (beside cutlist seeking pixelizations at very beginning of recording); on many LiveTV channels program transitions now are now hard to notice at all.

comment:16 Changed 13 months ago by stichnot

  • Resolution Works for me deleted
  • Status changed from closed to new

Changed 13 months ago by blm-ubunet@…

git diff against master branch

comment:17 Changed 13 months ago by blm-ubunet@…

For what it's worth..Attached "git diff" to master branch...

  • change to avformatdecoder.cpp not required.
  • Not tested with real tuner just "demo recorder from file" & VDPAU playback.
  • duration seems wrong. (same as before)
  • Result on master is inconclusive as master branch is unproven (here).

comment:18 Changed 13 months ago by warpme@…

@blm-ubunet, thx for Your's really nice/interesting work with this ticket. Just FYI: for 60+ TV channels (approx. 40 are H264 HD) I have excellent results - except single 1 channel. This particular channel gives me cycle of few sec of good screen, next few sec. black screen, next few sec. of total mess and again fes sec of good screen). If You are interested in details/debugging - pls PM me at warpme(at)o2.pl. Thx

comment:19 Changed 13 months ago by blm-ubunet@…

Small additional mod to un-break/block audio only & no-audio-no-video streams.
Tested audio only streams work on 0.26+fixes with no regression to video streams.

A fresh "git diff" to master branch attached..

Changed 13 months ago by blm-ubunet@…

fresh git diff to master with non-video stream unblocked.

comment:20 Changed 13 months ago by blm-ubunet@…

fix to my patch to play "warpme's" problem file..The file video has profile_idc=100 & that tested the scaling list code changes..

Changed 13 months ago by blm-ubunet@…

git diff to master..fix for warpme problem recording

comment:21 Changed 13 months ago by jpoet

  • Owner changed from stichnot to jpoet
  • Status changed from new to accepted

I have not tried to run this patch yet, but in general the git_diff.2.txt patch looks good. I believe it breaks back-to-back recording processing, though.

For back-to-back recordings, we don't actually shut down reading from the capture device, we just switch writing to a new ringbuffer. The new ringbuffer should start on a payload with a keyframe (and SPS?). To accomplish this we need to start buffering at the beginning of each payload until we know if that payload contains a keyframe (or SPS?). As soon as I have time to work out what changes need made to fix back-to-back recordings, I will see about getting this committed.

blm, thank you for taking the time to sift through the H.264 documentation and enhance myth's decoder. Please also note that using pre-increment of variables is always preferred over post-increment, unless there is a specific reason to use post-increment.

comment:22 Changed 12 months ago by blm-ubunet@…

Glad to be able to contribute.
Sorry I failed to realise the cost of post-inc & as there are no "continue" in the for loops..pre-inc is better.

I have been running back-to-back recordings (with 2 min extra on ends) just fine..

I have tweaked the patch a little..
H264:

  • was not honouring the SEQ start flag; always waited for seen_SPS.
  • parser has pre-increments

MPEG2:
Reading H262 standard...recordings should start on a sequence header.

  • setup same logic as H264.

IMO the dtvrecorder logic is much clearer & could still be reduced a bit more..

All my H264 samples still play okay inc 16:9 -> 4:3 transitions.
Have not tested mpeg2 video recording.

I'll have to try with demo/dummy recorder from the one mpeg2 file I have or find a willing tester..

Changed 12 months ago by blm-ubunet@…

git diff to master ; added some mpeg2 video changes etc

comment:23 Changed 12 months ago by blm-ubunet@…

I'm not sure this is a valid method but..
Tested patch "git_diff3.txt" with mpeg2 video recording via the "demo test recorder" dummy recorder.

I used the "CheeseSlices?" de-interlacing test-track Slicies_MPEG2_PAL_1080i_25.ts (33 sec) & recorded for 10 min.
Playback (mpeg2 vdpau) is seamless, seeking is fine, cut-list nav/seeking is fine.

comment:24 Changed 12 months ago by warpme@…

Hi, FYI: in my case git_diff3.txt has little regression over previous patches: program transitions on H264 channels now have pixelizations, while in previous versions were smooth. Also i have impression more channels now have exactly 15sec delay between program transitions (t.b.c.)

comment:25 Changed 12 months ago by blm-ubunet@…

You have to have "Wait SEQ start" set in the backend DVB tuner setup..
The additional change to H264 patch is to honour that setting.

All my samples. including your problem file, play fine.

Can you please find & check that setting ?
Do you have any mpeg2video sources ?

comment:26 Changed 12 months ago by warpme@…

Well - looking on "dvb_wait_for_seqstart" on DB level I have set to 1 for all tuners. Regarding mpeg2video - yes. I have over 20+ DVB SD (mpeg2) TV channels.

comment:27 Changed 12 months ago by blm-ubunet@…

I could well have made a typo..
My production system is 0.26+fixes. Git master is on another..
So to make the git-diff file there are several unreliable steps involving copying & "diff" & editing.
I did a simple playback only check on master.

comment:28 Changed 12 months ago by warpme@…

Oh - well - I'm on 0.26-fixes ad well :-)))). All Your's patches I backported to 0.26. After backporting I'm visually comparing source and backport - so I don't believe issue is in my backporting process. May You pls attach here last patch version for 0.26-fixes ?

Changed 12 months ago by blm-ubunet@…

git diff to master. Rearranged reset of _seen_sps so that only occurs with payload start & is similar to PES_sync.

comment:29 Changed 12 months ago by warpme@…

git-diff4 solves problem with H264 pixelizations. Generally H264 channels are recording/playing perfectly now. However MPEG2 recording seems to be completely broken. MPEG2 playback is OK with nice and fast seeks/jumps. MPEG2 recording starts 15-30sec then there is few flashes on screen, audio is completely gurgles and soon playback hangs. Pls find log from backend for MPEG2 channel LiveTV:

2013-04-17 10:29:22.310027 I  Getting next free recorder after : -1
 2013-04-17 10:29:22.310039 I  Checking card 1. Best card so far -1
 2013-04-17 10:29:22.311085 I  Checking card 2. Best card so far 1
 2013-04-17 10:29:22.311810 I  Checking card 3. Best card so far 1
 2013-04-17 10:29:22.312836 I  Checking card 4. Best card so far 1
 2013-04-17 10:29:22.313784 I  Checking card 5. Best card so far 1
 2013-04-17 10:29:22.314655 I  Checking card 6. Best card so far 5
 2013-04-17 10:29:22.315588 I  Checking card 7. Best card so far 5
 2013-04-17 10:29:22.316569 I  Checking card 8. Best card so far 5
 2013-04-17 10:29:22.317537 I  Checking card 9. Best card so far 5
 2013-04-17 10:29:22.318310 I  Checking card 10. Best card so far 9
 2013-04-17 10:29:22.321752 I  Checking card 18. Best card so far 17
 2013-04-17 10:29:22.322134 I  Checking card 19. Best card so far 17
 2013-04-17 10:29:22.322630 I  Checking card 20. Best card so far 17
 2013-04-17 10:29:22.323023 I  Best card is 17
 2013-04-17 10:29:22.328387 I  MainServer::ANN Playback
 2013-04-17 10:29:22.328394 I  adding: FE-Devel as a client (events: 0)
 2013-04-17 10:29:22.369821 I  TVRec(17): Found channel (44) on current card(17).
 2013-04-17 10:29:22.381836 I  TVRec(17): Changing from None to WatchingLiveTV
 2013-04-17 10:29:22.381857 I  TVRec(17): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady,
 2013-04-17 10:29:22.381871 I  TVRec(17): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
 2013-04-17 10:29:22.381884 I  ChannelBase(17): Looking for startchannel '44' on input 'DVBInput'
 2013-04-17 10:29:22.384702 I  ChannelBase(17): Found startchannel '44' on input 'DVBInput'
 2013-04-17 10:29:22.385421 I  TVRec(17): HW Tuner: 17->17
 2013-04-17 10:29:22.385435 I  TVRec(17): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
 2013-04-17 10:29:22.385445 I  TVRec(17): No recorder yet, calling TuningFrequency
 2013-04-17 10:29:22.385778 I  DVBChan(17:/dev/dvb/adapter8/frontend0): Opening DVB channel
 2013-04-17 10:29:22.385786 I  DTVChan(/dev/dvb/adapter8/frontend0): SetChannelByString(44):
 2013-04-17 10:29:22.387968 I  DVBChan(17:/dev/dvb/adapter8/frontend0): 11158000 qpsk a auto auto a a auto a v fec: 5/6 msys: DVB-S rolloff: 0.35
 2013-04-17 10:29:22.388035 I  DVBChan(17:/dev/dvb/adapter8/frontend0):
 Old Params: 11158000 qpsk a auto auto a a auto a v fec: 5/6 msys: DVB-S rolloff: 0.35
 New Params: 11158000 qpsk a auto auto a a auto a v fec: 5/6 msys: DVB-S rolloff: 0.35
 2013-04-17 10:29:22.388043 I  DVBChan(17:/dev/dvb/adapter8/frontend0): Tune(): Frequency tuning successful.
 2013-04-17 10:29:22.388047 I  DTVChan(/dev/dvb/adapter8/frontend0): SetChannelByString(44): success
 2013-04-17 10:29:22.388058 I  TVRec(17): CreateLiveTVRingBuffer(44)
 2013-04-17 10:29:22.388563 I  TVRec(17): GetProgramRingBufferForLiveTV()
 2013-04-17 10:29:22.390288 N  AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
 2013-04-17 10:29:22.416668 I  TVRec(17): StartedRecording(21109_2013-04-17T08:29:22Z) fn(/myth/tv/21109_20130417082922.mpg)
 2013-04-17 10:29:22.418716 I  Chain: Appended@0 '21109_20130417082922'
 2013-04-17 10:29:22.419895 I  TVRec(17): Starting Signal Monitor
 2013-04-17 10:29:22.419907 I  TVRec(17): SetupSignalMonitor(1, 1)
 2013-04-17 10:29:22.419916 I  DVBChan(17:/dev/dvb/adapter8/frontend0): Opening DVB channel
 2013-04-17 10:29:22.423066 I  DVBSM(/dev/dvb/adapter8/frontend0): Can measure Signal Strength
 2013-04-17 10:29:22.427909 I  DVBSM(/dev/dvb/adapter8/frontend0): Can measure S/N
 2013-04-17 10:29:22.430091 I  DVBSM(/dev/dvb/adapter8/frontend0): Can measure Bit Error Rate
 2013-04-17 10:29:22.433490 I  DVBSM(/dev/dvb/adapter8/frontend0): Can count Uncorrected Blocks
 2013-04-17 10:29:22.433508 I  DVBSM(/dev/dvb/adapter8/frontend0): DVBSignalMonitor::ctor initial flags Seen() Match() Wait(Sig,SNR,BER,UB,)
 2013-04-17 10:29:22.433535 I  TVRec(17): Signal monitor successfully created
 2013-04-17 10:29:22.433541 I  TVRec(17): Setting up table monitoring.
 2013-04-17 10:29:22.434649 I  Using profile 'Live TV' to record
 2013-04-17 10:29:22.434667 I  TVRec(17): MPEG program number: 13109
 2013-04-17 10:29:22.434684 I  DTVSM(/dev/dvb/adapter8/frontend0)::SetProgramNumber(13109):
 2013-04-17 10:29:22.434701 I  TVRec(17): Successfully set up MPEG table monitoring.
 2013-04-17 10:29:22.439067 I  TVRec(17): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
 2013-04-17 10:29:22.439079 I  TVRec(17): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
 2013-04-17 10:29:22.439086 I  TVRec(17): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady,
 2013-04-17 10:29:22.439094 I  TVRec(17): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.439097 I  DummyDTVRecorder -- started
 2013-04-17 10:29:22.439104 I  TVRec(17): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.439111 I  TVRec(17): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.439117 I  TVRec(17): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.439179 I  TVRec(17): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.452663 I  DVBSM(/dev/dvb/adapter8/frontend0): Signal Locked
 2013-04-17 10:29:22.452682 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- begin
 2013-04-17 10:29:22.452687 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- locked
 2013-04-17 10:29:22.452771 I  DVBSH(/dev/dvb/adapter8/frontend0): run(): begin
 2013-04-17 10:29:22.453399 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): begin
 2013-04-17 10:29:22.453446 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x0
 2013-04-17 10:29:22.453564 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x1
 2013-04-17 10:29:22.495207 I  CreatePATSingleProgram()
 2013-04-17 10:29:22.495215 I  PAT in input stream
 2013-04-17 10:29:22.495262 I  Program Association Section
 PSIP tableID(0x0) length(69) extension(0x3390)
 version(0) current(1) section(0) last_section(0)
 tsid(13200) programCount(15)
 program number     0 has PID 0x0010
 program number 13101 has PID 0x0021
 program number 13102 has PID 0x0022
 program number 13103 has PID 0x0023
 program number 13104 has PID 0x0024
 program number 13105 has PID 0x0025
 program number 13106 has PID 0x0026
 program number 13107 has PID 0x0027
 program number 13108 has PID 0x0028
 program number 13109 has PID 0x0029
 program number 13110 has PID 0x002a
 program number 13122 has PID 0x0032
 program number 13126 has PID 0x0036
 program number 13129 has PID 0x0039
 program number 13139 has PID 0x0043
 2013-04-17 10:29:22.495266 I  desired_program(13109) pid(0x29)
 2013-04-17 10:29:22.495286 I  pmt_pid(0x29)
 2013-04-17 10:29:22.495288 I  PAT for output stream
 2013-04-17 10:29:22.495303 I  Program Association Section
 PSIP tableID(0x0) length(13) extension(0x3390)
 version(0) current(1) section(0) last_section(0)
 tsid(13200) programCount(1)
 program number     1 has PID 0x0029
 2013-04-17 10:29:22.495371 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x29
 2013-04-17 10:29:22.495628 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x83
 2013-04-17 10:29:22.495803 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x86
 2013-04-17 10:29:22.496004 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x1ffe
 2013-04-17 10:29:22.552851 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- end
 2013-04-17 10:29:22.595621 N  DTVSM(/dev/dvb/adapter8/frontend0): PMT says program 13109 is encrypted
 2013-04-17 10:29:22.595690 I  CreatePMTSingleProgram()
 2013-04-17 10:29:22.595693 I  PMT in input stream
 2013-04-17 10:29:22.595843 I  Program Map Section
 PSIP tableID(0x2) length(280) extension(0x3335)
 version(1) current(1) section(0) last_section(0)
 pnum(13109) pid(0x29)
 Multiplex Buffer Utilization Descriptor (0x0c) length(4)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(178) Descriptor (0xb2) length(57)
 Conditional Access: sid(0x1861) pid(0x18a) data_size(0)
 Conditional Access: sid(0x1803) pid(0x18b) data_size(0)
 Conditional Access: sid(0x100) pid(0x18c) data_size(13)
 Conditional Access: sid(0x500) pid(0x18f) data_size(11)
 Conditional Access: sid(0x1813) pid(0x18c) data_size(3)
 Stream #0 pid(0x181) type(0x02 video-mpeg2)
 Stream Identifier Descriptor (0x52): ComponentTag=0x1
 Video Descriptor (0x02) length(3)
 Data Stream Alignment Descriptor (0x06) length(1)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #1 pid(0x182) type(0x04 audio-mp2-layer[1,2,3])
 Stream Identifier Descriptor (0x52): ComponentTag=0x2
 ISO-639 Language: code(pol) canonical(pol) eng(Polish)
 Audio Descriptor (0x03) length(1)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #2 pid(0x184) type(0x06 private-data)
 Stream Identifier Descriptor (0x52): ComponentTag=0x3
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #3 pid(0xd0) type(0xc0 unknown)
 Unknown(198) Descriptor (0xc6) length(5)
 Unknown(194) Descriptor (0xc2) length(24)
 Stream #4 pid(0xd5) type(0xc1 unknown)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(194) Descriptor (0xc2) length(8)
 Stream #5 pid(0x108) type(0x06 private-data)
 Stream Identifier Descriptor (0x52): ComponentTag=0x5
 Teletext Descriptor: 2 pages
 type(1) mag(1) page(00) lang(pol)
 type(2) mag(7) page(83) lang(pol)
 2013-04-17 10:29:22.595918 I  PMT for output stream
 2013-04-17 10:29:22.596015 I  Program Map Section
 PSIP tableID(0x2) length(217) extension(0x1)
 version(1) current(1) section(0) last_section(0)
 pnum(1) pid(0x29)
 Multiplex Buffer Utilization Descriptor (0x0c) length(4)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(178) Descriptor (0xb2) length(57)
 Stream #0 pid(0x181) type(0x02 video-mpeg2)
 Stream Identifier Descriptor (0x52): ComponentTag=0x1
 Video Descriptor (0x02) length(3)
 Data Stream Alignment Descriptor (0x06) length(1)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #1 pid(0x182) type(0x04 audio-mp2-layer[1,2,3])
 Stream Identifier Descriptor (0x52): ComponentTag=0x2
 ISO-639 Language: code(pol) canonical(pol) eng(Polish)
 Audio Descriptor (0x03) length(1)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #2 pid(0x184) type(0x06 private-data)
 Stream Identifier Descriptor (0x52): ComponentTag=0x3
 Maximum Bitrate Descriptor (0x0e) length(3)
 Stream #3 pid(0xd0) type(0xc0 unknown)
 Unknown(198) Descriptor (0xc6) length(5)
 Unknown(194) Descriptor (0xc2) length(24)
 Stream #4 pid(0xd5) type(0xc1 unknown)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(194) Descriptor (0xc2) length(8)
 Stream #5 pid(0x108) type(0x06 private-data)
 Stream Identifier Descriptor (0x52): ComponentTag=0x5
 Teletext Descriptor: 2 pages
 type(1) mag(1) page(00) lang(pol)
 type(2) mag(7) page(83) lang(pol)
 2013-04-17 10:29:22.596076 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0xd0
 2013-04-17 10:29:22.596188 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0xd5
 2013-04-17 10:29:22.596411 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x108
 2013-04-17 10:29:22.596494 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x181
 2013-04-17 10:29:22.596572 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x182
 2013-04-17 10:29:22.596648 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x184
 2013-04-17 10:29:22.596742 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18a
 2013-04-17 10:29:22.596853 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18b
 2013-04-17 10:29:22.596962 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18c
 2013-04-17 10:29:22.597077 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18e
 2013-04-17 10:29:22.597151 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18f
 2013-04-17 10:29:22.748674 I  PID 0x181 status: Decrypted
 2013-04-17 10:29:22.748816 I  PID 0x182 status: Decrypted
 2013-04-17 10:29:22.748821 I  Program 13109 status: Decrypted
 2013-04-17 10:29:22.753940 I  TVRec(17): Got good signal
 2013-04-17 10:29:22.753994 I  TVRec(17): TeardownSignalMonitor() -- begin
 2013-04-17 10:29:22.754003 I  DVBSM(/dev/dvb/adapter8/frontend0): Stop() -- begin
 2013-04-17 10:29:22.804358 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- begin
 2013-04-17 10:29:22.804367 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- locked
 2013-04-17 10:29:22.849530 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): shutdown
 2013-04-17 10:29:22.849557 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x0
 2013-04-17 10:29:22.849661 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x1
 2013-04-17 10:29:22.849820 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x29
 2013-04-17 10:29:22.849884 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x83
 2013-04-17 10:29:22.849987 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x86
 2013-04-17 10:29:22.850085 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0xd0
 2013-04-17 10:29:22.850128 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0xd5
 2013-04-17 10:29:22.850169 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x108
 2013-04-17 10:29:22.850259 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x181
 2013-04-17 10:29:22.850370 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x182
 2013-04-17 10:29:22.850474 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x184
 2013-04-17 10:29:22.850509 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18a
 2013-04-17 10:29:22.850607 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18b
 2013-04-17 10:29:22.850702 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18c
 2013-04-17 10:29:22.850740 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18e
 2013-04-17 10:29:22.850777 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18f
 2013-04-17 10:29:22.850813 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x1ffe
 2013-04-17 10:29:22.851016 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): end
 2013-04-17 10:29:22.851030 I  DVBSH(/dev/dvb/adapter8/frontend0): run(): end
 2013-04-17 10:29:22.851162 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- end
 2013-04-17 10:29:22.851169 I  DVBSM(/dev/dvb/adapter8/frontend0): Stop() -- end
 2013-04-17 10:29:22.851207 I  TVRec(17): TeardownSignalMonitor() -- end
 2013-04-17 10:29:22.851217 I  TVRec(17): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.851226 I  TVRec(17): ClearFlags(WaitingForSignal,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.851539 I  EITScanner (17): Started passive scan.
 2013-04-17 10:29:22.851545 I  TVRec(17): Starting Recorder
 2013-04-17 10:29:22.851908 I  TVRec(17): FinishedRecording(21109_2013-04-17T08:29:22Z)
 title: Serwis...
 in recgroup: LiveTV status: Nagrywam:Nagrane is_dummy finished_now
 2013-04-17 10:29:22.852507 I  Chain: Updated endtime for '21109_20130417082922' to 20130417082922
 2013-04-17 10:29:22.853240 I  TVRec(17): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
 2013-04-17 10:29:22.855155 I  Using profile 'Live TV' to record
 2013-04-17 10:29:22.855182 I  TVRec(17): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(21109_2013-04-17T08:29:22Z) curRec.size(0)
 2013-04-17 10:29:22.855598 I  TVRec(17): GetProgramRingBufferForLiveTV()
 2013-04-17 10:29:22.857293 N  AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
 2013-04-17 10:29:22.880172 E  RecordingInfo::InsertProgram(ProgramInfo(21109_20130417082922.mpg): channame(Polsat News) startts(Wed Apr 17 08:00:00 2013) endts(Wed Apr 17 08:30:00 2013)
 recstartts(Wed Apr 17 08:29:22 2013) recendts(Wed Apr 17 08:30:00 2013)
 title(Serwis...)): recording already exists...
 2013-04-17 10:29:22.882091 I  TVRec(17): StartedRecording(21109_2013-04-17T08:29:23Z) fn(/myth/tv/21109_20130417082923.mpg)
 2013-04-17 10:29:22.884456 I  Chain: Appended@1 '21109_20130417082923'
 2013-04-17 10:29:22.886989 I  DTVRec(17): ResetForNewFile(void)
 2013-04-17 10:29:22.887024 I  RecBase(17:/dev/dvb/adapter8/frontend0): SetRingBuffer(0x7f084c124600) '/myth/tv/21109_20130417082923.mpg'
 2013-04-17 10:29:22.887059 I  DTVRec(17): SetPAT(13109 on 0x29)
 2013-04-17 10:29:22.887085 I  CreatePATSingleProgram()
 2013-04-17 10:29:22.887087 I  PAT in input stream
 2013-04-17 10:29:22.887129 I  Program Association Section
 PSIP tableID(0x0) length(69) extension(0x3390)
 version(0) current(1) section(0) last_section(0)
 tsid(13200) programCount(15)
 program number     0 has PID 0x0010
 program number 13101 has PID 0x0021
 program number 13102 has PID 0x0022
 program number 13103 has PID 0x0023
 program number 13104 has PID 0x0024
 program number 13105 has PID 0x0025
 program number 13106 has PID 0x0026
 2013-04-17 10:29:22.887134 I  desired_program(13109) pid(0x29)
 2013-04-17 10:29:22.887150 I  pmt_pid(0x29)
 2013-04-17 10:29:22.887152 I  PAT for output stream
 2013-04-17 10:29:22.887166 I  Program Association Section
 PSIP tableID(0x0) length(13) extension(0x3390)
 version(0) current(1) section(0) last_section(0)
 tsid(13200) programCount(1)
 program number     1 has PID 0x0029
 2013-04-17 10:29:22.887193 I  DTVRec(17): SetPMT(13109)
 2013-04-17 10:29:22.887221 I  CreatePMTSingleProgram()
 2013-04-17 10:29:22.887224 I  PMT in input stream
 2013-04-17 10:29:22.887359 I  Program Map Section
 PSIP tableID(0x2) length(280) extension(0x3335)
 version(1) current(1) section(0) last_section(0)
 pnum(13109) pid(0x29)
 Multiplex Buffer Utilization Descriptor (0x0c) length(4)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(178) Descriptor (0xb2) length(57)
 Conditional Access: sid(0x1861) pid(0x18a) data_size(0)
 Conditional Access: sid(0x1803) pid(0x18b) data_size(0)
 Conditional Access: sid(0x100) pid(0x18c) data_size(13)
 Conditional Access: sid(0xb01) pid(0x18e) data_size(0)
 2013-04-17 10:29:22.887438 I  PMT for output stream
 2013-04-17 10:29:22.887543 I  Program Map Section
 PSIP tableID(0x2) length(217) extension(0x1)
 version(1) current(1) section(0) last_section(0)
 pnum(1) pid(0x29)
 Multiplex Buffer Utilization Descriptor (0x0c) length(4)
 Maximum Bitrate Descriptor (0x0e) length(3)
 Unknown(178) Descriptor (0xb2) length(57)
 Stream #0 pid(0x181) type(0x02 video-mpeg2)
 Stream Identifier Descriptor (0x52): ComponentTag=0x1
 Video Descriptor (0x02) length(3)
 Data Stream Alignment Descriptor (0x06) length(1)
 2013-04-17 10:29:22.887564 I  RecBase(17:/dev/dvb/adapter8/frontend0): SetRecording(0x7f084c19bf10) title(Serwis...)
 2013-04-17 10:29:22.887893 I  TVRec(17): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
 2013-04-17 10:29:22.888127 I  DTVRec(17): ResetForNewFile(void)
 2013-04-17 10:29:22.888152 I  DVBRec(17:/dev/dvb/adapter8/frontend0): Card opened successfully
 2013-04-17 10:29:22.888188 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- begin
 2013-04-17 10:29:22.888194 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- locked
 2013-04-17 10:29:22.888276 I  DVBSH(/dev/dvb/adapter8/frontend0): run(): begin
 2013-04-17 10:29:22.893158 I  TVRec(17): SetFlags(RecorderRunning,RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.893178 I  TVRec(17): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
 2013-04-17 10:29:22.925449 I  DevRdB(/dev/dvb/adapter8/frontend0): buffer size 32900 KB
 2013-04-17 10:29:22.926593 I  DevRdB(/dev/dvb/adapter8/frontend0): Start() -- begin
 2013-04-17 10:29:22.926663 I  DevRdB(/dev/dvb/adapter8/frontend0): Start() -- middle
 2013-04-17 10:29:22.926668 I  DevRdB(/dev/dvb/adapter8/frontend0): Start() -- end
 2013-04-17 10:29:22.926672 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): begin
 2013-04-17 10:29:22.926740 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x0
 2013-04-17 10:29:22.926865 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x1
 2013-04-17 10:29:22.926944 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x10
 2013-04-17 10:29:22.927182 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x14
 2013-04-17 10:29:22.927261 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x21
 2013-04-17 10:29:22.927751 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x22
 2013-04-17 10:29:22.927814 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x23
 2013-04-17 10:29:22.927865 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x24
 2013-04-17 10:29:22.927983 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x25
 2013-04-17 10:29:22.928039 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x26
 2013-04-17 10:29:22.928124 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x27
 2013-04-17 10:29:22.928229 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x28
 2013-04-17 10:29:22.928761 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x29
 2013-04-17 10:29:22.929025 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x2a
 2013-04-17 10:29:22.929387 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x32
 2013-04-17 10:29:22.929451 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x36
 2013-04-17 10:29:22.929512 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x39
 2013-04-17 10:29:22.929571 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x43
 2013-04-17 10:29:22.929631 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x83
 2013-04-17 10:29:22.929690 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x86
 2013-04-17 10:29:22.929750 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0xd0
 2013-04-17 10:29:22.929828 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0xd5
 2013-04-17 10:29:22.929890 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x108
 2013-04-17 10:29:22.929952 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x181
 2013-04-17 10:29:22.930026 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x182
 2013-04-17 10:29:22.930097 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x184
 2013-04-17 10:29:22.930163 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18a
 2013-04-17 10:29:22.930230 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18b
 2013-04-17 10:29:22.930298 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18c
 2013-04-17 10:29:22.930367 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18e
 2013-04-17 10:29:22.930745 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x18f
 2013-04-17 10:29:22.930972 I  PIDInfo(/dev/dvb/adapter8/frontend0): Opening filter for pid 0x1ffe
 2013-04-17 10:29:22.950232 I  MainServer::ANN Playback
 2013-04-17 10:29:22.950240 I  adding: fe-devel as a client (events: 0)
 2013-04-17 10:29:22.952053 I  MainServer::HandleAnnounce FileTransfer
 2013-04-17 10:29:22.952060 I  adding: fe-devel as a remote file transfer
 2013-04-17 10:29:22.988401 I  SH(/dev/dvb/adapter8/frontend0): AddListener(0x7f084c028180) -- end
 2013-04-17 10:29:23.185951 I  DTVRec(17): FindMPEG2Keyframes: frame rate = 25000
 2013-04-17 10:29:23.186091 I  DTVRec(17): PID 0x181 Found Payload Start
 2013-04-17 10:29:23.186122 I  DTVRec(17): PID 0x182 Found Payload Start
 2013-04-17 10:29:24.222619 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:24.249353 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:25.156137 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:25.401827 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:26.368775 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:27.368924 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:27.395690 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:28.362650 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:29.329563 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:32.130627 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:32.195923 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:32.742085 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:32.807371 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:33.052943 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:33.719372 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:33.784629 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:34.030299 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:34.876956 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:34.942267 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:35.187948 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:35.794269 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:35.859531 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:38.600622 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:38.906268 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:39.452358 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:39.517664 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:39.763247 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:40.068969 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:40.134288 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:40.379912 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:41.346625 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:41.411942 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:42.018234 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:43.306731 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:43.852888 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:43.918199 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:44.103788 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:44.169002 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:44.835363 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:44.900612 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:45.146212 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:46.052861 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:46.118134 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:47.085056 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:48.074394 I  RecBase(17:/dev/dvb/adapter8/frontend0): GetKeyframePositions(607,9223372036854775807,#0) out of 29
 2013-04-17 10:29:49.089253 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:49.154580 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:49.640710 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:49.706010 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:49.951685 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:50.858381 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:50.923693 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:51.890524 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:51.955839 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:52.862698 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:52.928005 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:53.902475 I  RecBase(17:/dev/dvb/adapter8/frontend0): GetKeyframePositions(607,9223372036854775807,#6) out of 35
 2013-04-17 10:29:55.478395 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:55.543669 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:55.789307 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:56.696113 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:56.761381 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:57.761524 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:57.788301 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:58.695015 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:29:58.760286 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:00.915253 I  TVRec(17): Switching Buffer (!has_rec(0) && !rec_soon(0) && (2013-04-17T08:30:00Z >= 2013-04-17T08:30:00Z(1) ))
 2013-04-17 10:30:00.915279 I  TVRec(17): SwitchLiveTVRingBuffer(discont 0, set_next_rec 1) curRec(21109_2013-04-17T08:29:23Z) curRec.size(0)
 2013-04-17 10:30:00.915638 I  TVRec(17): GetProgramRingBufferForLiveTV()
 2013-04-17 10:30:00.917640 N  AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 14 min
 2013-04-17 10:30:00.949840 I  TVRec(17): StartedRecording(21109_2013-04-17T08:30:00Z) fn(/myth/tv/21109_20130417083000.mpg)
 2013-04-17 10:30:00.952004 I  Chain: Appended@2 '21109_20130417083000'
 2013-04-17 10:30:00.952048 I  DTVRec(17): SetNextRecord(0x7f084c1995f0, 0x7f084c03eb80)
 2013-04-17 10:30:00.952823 I  TVRec(17): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
 2013-04-17 10:30:00.952832 I  TVRec(17): Enabling Full LiveTV UI.
 2013-04-17 10:30:00.952860 I  Waiting for ringbuffer switch
 2013-04-17 10:30:00.952863 I  TVRec(17): Enabling Full LiveTV UI.
 2013-04-17 10:30:01.187985 I  RecordingQuality() start(2013-04-17T08:00:00Z) end(2013-04-17T08:30:00Z) score(0)
 2013-04-17 10:30:01.187998 I  DTVRec(17): ResetForNewFile(void)
 2013-04-17 10:30:01.188019 I  RecBase(17:/dev/dvb/adapter8/frontend0): SetRingBuffer(0x7f084c03eb80) '/myth/tv/21109_20130417083000.mpg'
 2013-04-17 10:30:01.188027 I  RecBase(17:/dev/dvb/adapter8/frontend0): SetRecording(0x7f084c16ee00) title(Serwis...)
 2013-04-17 10:30:01.188068 I  TVRec(17): RingBufferChanged()
 2013-04-17 10:30:01.188662 I  TVRec(17): FinishedRecording(21109_2013-04-17T08:29:23Z) damaged recq:<RecordingQuality overall_score="0" key="21109_2013-04-17T08:29:23Z" countinuity_error_count="0" packet_count="95516">
 <Gap start="2013-04-17T08:00:00Z" end="2013-04-17T08:29:22Z" duration="1762" />
 </RecordingQuality>
 2013-04-17 10:30:01.188709 I  TVRec(17): FinishedRecording(21109_2013-04-17T08:29:23Z)
 title: Serwis...
 in recgroup: LiveTV status: Nieznany:Recorder Failed not_dummy finished_now
 2013-04-17 10:30:01.189183 I  Chain: Updated endtime for '21109_20130417082923' to 20130417083001
 2013-04-17 10:30:01.189968 I  SaveVideoProperties(0x38, 0x20)
 2013-04-17 10:30:01.195260 I  DTVRec(17): FindMPEG2Keyframes: frame rate = 25000
 2013-04-17 10:30:01.775150 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:02.775337 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:03.124203 W  RingBuf(/myth/tv/21109_20130417082923.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:05.923620 N  Expiring 4 MB for 21109 at 2013-04-17T08:26:09Z => Serwis...:"Serwis informacyjny, Pogoda"
 2013-04-17 10:30:05.923659 N  Expiring 0 MB for 21109 at 2013-04-17T08:27:23Z => Serwis...:"Serwis informacyjny, Pogoda"
 2013-04-17 10:30:05.923683 N  Expiring 2 MB for 21109 at 2013-04-17T08:27:24Z => Serwis...:"Serwis informacyjny, Pogoda"
 2013-04-17 10:30:05.923706 N  Expiring 4 MB for 21109 at 2013-04-17T08:28:03Z => Serwis...:"Serwis informacyjny, Pogoda"
 2013-04-17 10:30:13.781114 I  MainServer::ANN Playback
 2013-04-17 10:30:13.781123 I  adding: fe-devel as a client (events: 0)
 2013-04-17 10:30:13.782878 I  MainServer::HandleAnnounce FileTransfer
 2013-04-17 10:30:13.782884 I  adding: fe-devel as a remote file transfer
 2013-04-17 10:30:13.834441 I  RecBase(17:/dev/dvb/adapter8/frontend0): GetKeyframePositions(289,9223372036854775807,#1) out of 14
 2013-04-17 10:30:16.076372 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:16.802994 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:17.048496 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:17.775001 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:18.020587 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:19.020732 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:19.047515 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:20.047659 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:22.630061 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:22.695333 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:22.940969 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:23.547196 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:23.612464 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:23.858031 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:24.825108 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:24.890489 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:25.556776 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:28.904409 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:29.811185 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:29.876503 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:30.723242 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:30.788554 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:31.034424 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:31.941298 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:32.006465 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:32.973170 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:33.038458 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:35.042727 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:35.949237 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:36.014615 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:37.014772 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:37.101757 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:37.166978 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:38.133868 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:38.199125 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:39.105903 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:39.171146 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:39.416705 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:40.383540 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:40.448818 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:41.355595 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:41.420880 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:42.421037 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:44.512233 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:45.479029 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:45.544310 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:46.451007 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:46.516303 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:47.423075 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:47.488297 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:48.455248 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:48.520535 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:49.427357 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:49.492651 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:50.459526 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:50.524803 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:51.431554 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:52.790255 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:53.456621 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:53.521930 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:53.767486 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:54.433964 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:54.499283 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:54.744908 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:55.351096 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:55.416412 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:55.661996 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:57.616715 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:58.343216 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:58.408504 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:30:58.654267 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:00.493651 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:00.558974 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:02.578606 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:02.643966 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:03.610919 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:03.616058 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:03.681314 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:04.287620 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:04.352841 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:04.478251 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:07.349622 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:07.414897 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:07.660436 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:08.266633 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:08.331879 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:08.577461 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:09.484160 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:09.549401 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:10.516174 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:10.581452 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:11.067808 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:13.327750 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:13.573278 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:14.179414 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:14.244689 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:14.430092 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:14.495355 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:15.281941 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:15.347225 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:15.592849 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:16.259097 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:18.289055 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:19.015489 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:19.080694 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:19.266196 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:19.331521 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:19.817527 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:21.661907 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:21.727219 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:21.912750 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:21.978015 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:22.764508 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:22.829742 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:23.075405 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:24.849262 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:25.455445 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:25.520762 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:25.766367 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:26.432762 W  RingBuf(/myth/tv/21109_20130417083000.mpg): Taking too long to be allowed to read..
 2013-04-17 10:31:26.510873 I  TVRec(17): StopLiveTV(void) curRec: 0x7f082c2e6ae0 pseudoRec: 0x0
 2013-04-17 10:31:26.511621 I  TVRec(17): Changing from WatchingLiveTV to None
 2013-04-17 10:31:26.512238 I  TVRec(17): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
 2013-04-17 10:31:26.512256 I  TVRec(17): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
 2013-04-17 10:31:26.512320 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- begin
 2013-04-17 10:31:26.512333 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- locked
 2013-04-17 10:31:26.512340 I  DevRdB(/dev/dvb/adapter8/frontend0): Stop() -- begin
 2013-04-17 10:31:26.512497 I  DevRdB(/dev/dvb/adapter8/frontend0): Stop() -- end
 2013-04-17 10:31:26.512646 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): shutdown
 2013-04-17 10:31:26.512674 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x0
 2013-04-17 10:31:26.512818 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x1
 2013-04-17 10:31:26.512912 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x10
 2013-04-17 10:31:26.512957 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x14
 2013-04-17 10:31:26.513063 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x21
 2013-04-17 10:31:26.513127 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x22
 2013-04-17 10:31:26.513237 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x23
 2013-04-17 10:31:26.513297 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x24
 2013-04-17 10:31:26.513348 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x25
 2013-04-17 10:31:26.513390 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x26
 2013-04-17 10:31:26.513438 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x27
 2013-04-17 10:31:26.513484 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x28
 2013-04-17 10:31:26.513548 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x29
 2013-04-17 10:31:26.513633 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x2a
 2013-04-17 10:31:26.513678 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x32
 2013-04-17 10:31:26.513764 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x36
 2013-04-17 10:31:26.513851 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x39
 2013-04-17 10:31:26.513889 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x43
 2013-04-17 10:31:26.513972 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x83
 2013-04-17 10:31:26.514019 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x86
 2013-04-17 10:31:26.514057 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0xd0
 2013-04-17 10:31:26.514098 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0xd5
 2013-04-17 10:31:26.514199 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x108
 2013-04-17 10:31:26.514337 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x181
 2013-04-17 10:31:26.514424 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x182
 2013-04-17 10:31:26.514477 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x184
 2013-04-17 10:31:26.514513 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18a
 2013-04-17 10:31:26.514608 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18b
 2013-04-17 10:31:26.514704 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18c
 2013-04-17 10:31:26.514739 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18e
 2013-04-17 10:31:26.514950 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x18f
 2013-04-17 10:31:26.515100 I  PIDInfo(/dev/dvb/adapter8/frontend0): Closing filter for pid 0x1ffe
 2013-04-17 10:31:26.515145 I  DevRdB(/dev/dvb/adapter8/frontend0): Stop() -- begin
 2013-04-17 10:31:26.515149 I  DevRdB(/dev/dvb/adapter8/frontend0): Stop() -- end
 2013-04-17 10:31:26.518077 I  DVBSH(/dev/dvb/adapter8/frontend0): RunTS(): end
 2013-04-17 10:31:26.518088 I  DVBSH(/dev/dvb/adapter8/frontend0): run(): end
 2013-04-17 10:31:26.519300 I  SH(/dev/dvb/adapter8/frontend0): RemoveListener(0x7f084c028180) -- end
 2013-04-17 10:31:26.519317 I  DVBRec(17:/dev/dvb/adapter8/frontend0): Close() -- begin
 2013-04-17 10:31:26.519347 I  DVBRec(17:/dev/dvb/adapter8/frontend0): Close() -- end
 2013-04-17 10:31:26.522461 I  TVRec(17): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
 2013-04-17 10:31:26.522518 I  RecordingQuality() start(2013-04-17T08:30:00Z) end(2013-04-17T09:00:00Z) score(0)
 2013-04-17 10:31:26.522715 I  RecBase(17:/dev/dvb/adapter8/frontend0): SetRecording(0x0)
 2013-04-17 10:31:26.523573 I  TVRec(17): FinishedRecording(21109_2013-04-17T08:30:00Z) damaged recq:<RecordingQuality overall_score="0" key="21109_2013-04-17T08:30:00Z" countinuity_error_count="0" packet_count="195650">
 <Gap start="2013-04-17T08:31:25Z" end="2013-04-17T09:00:00Z" duration="1714" />
 </RecordingQuality>
 2013-04-17 10:31:26.523615 I  TVRec(17): FinishedRecording(21109_2013-04-17T08:30:00Z)
 title: Serwis...
 in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
 2013-04-17 10:31:26.524098 I  Chain: Updated endtime for '21109_20130417083000' to 20130417083126
 2013-04-17 10:31:26.524986 I  SaveVideoProperties(0x38, 0x20)
 2013-04-17 10:31:26.527253 I  TVRec(17): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
 2013-04-17 10:31:26.527263 I  TVRec(17): Tearing down RingBuffer
 2013-04-17 10:31:26.527576 I  TVRec(17): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
 2013-04-17 10:31:26.528989 I  TVRec(17): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,RingBufferReady


comment:30 Changed 12 months ago by warpme@…

It's obvious but FYI: I can rather confirm removing following hunk seems to solve problem with MPEG2 recording. (it looks on logs it solves - as I tested it only remotely via SSH and exterminating BE/FE logs :-p)

@@ -419,7 +418,11 @@ bool DTVRecorder::FindMPEG2Keyframes(const TSPacket* tspacket)
     // looking for first byte of MPEG start code (3 bytes 0 0 1)
     // otherwise, pick up search where we left off.
     const bool payloadStart = tspacket->PayloadStart();
-    _start_code = (payloadStart) ? 0xffffffff : _start_code;
+    if (payloadStart)
+    {
+        _start_code = 0xffffffff;
+        _seen_sps = false;
+    }
 
     // Just make these local for efficiency reasons (gcc not so smart..)
     const uint maxKFD = kMaxKeyFrameDistance;


Changed 11 months ago by jpoet

Fix parsing of SEI_TYPE_RECOVERY_POINT

comment:31 Changed 11 months ago by jpoet

git-diff4-cleaned.txt​ breaks keyframe detection for HD-PVR recordings. With it all I frames are counted as keyframes, but on the HD-PVR they are not.

That patch does clean up a few areas, though, and possibly most importantly, fixes the parsing of SEI recovery points. It also fixes some variable initializations.

I have attached a simplified version (SPS-H264Parser.patch) which doesn't break the HD-PVR. I am hoping it fixes the problem(s) described on this ticket. If it doesn't, the fix might get nasty since we will need to come up with a way of fixing these problems without breaking it for other people.

Changed 11 months ago by jpoet

fixes/0.26 version

comment:32 Changed 11 months ago by jpoet

Added a 0.26 version of the patch.

comment:33 Changed 11 months ago by blm-ubunet@…

I don't think it breaks keyframe detection as such..problem is that the input data is dumped with no buffering because SPS is not seen.

My mistake because the H264 docs state that SPS/PPS do not have to be present in the same stream..
I suspect (from internet searches) that the hdpvr does not output SPS (or not often).

I don't like the idea of mushing parser states into one flag to avoid changing dtvrecorder but I understand your concerns..
A good soln could be to check for number keyframes passed without SPS & then start to write to file etc..
I have attached patch which does that.

This patch has no regressions with my international samples (playback) & local recording/ liveTV. In fact it has solved my problem with HLS (NasaTV) (liveTV).

I could try test hdpvr recording via dummy recorder but currently that assumes mpeg-ps.

Changed 11 months ago by blm-ubunet@…

allow for H264 stream without SPS but still use it if possible.

comment:34 Changed 11 months ago by blm-ubunet@…

After forcing dummy recorder to use H264 Parser & recording an hdpvr recording file..I get keyframes every 32 frames which is wrong should be every approx. 140 frames for 60fps.

Ah penny drops ..the flag "I_is_keyframe" was being set to false for hdpvr in mpegrecorder.cpp.
I removed that logic. There still must be a flaw in the keyframe logic because there should not be a special case for hdpvr.

Have yet to test this...

comment:35 Changed 10 months ago by warpme@…

FYI: I just give try for SPS-H264Parser-0.26.patch on current 0.26-fixes. Unfortunately "pixeled" edit with this patch returns. Also jumping forward/back is slower again (it has approx 1sec of slower playback just after jump and next playback becomes OK). With git-diff4-cleaned.txt​ I have OK working edit. Also jumps are really fast.

comment:36 Changed 10 months ago by jpoet

I am hoping to have more time to work on this soon. Do either of you have samples available that I can play with?

comment:37 Changed 10 months ago by warpme@…

Sure, I can put it on my FTP (PM me pls for access details) or upload to place convenient for You. Tested recordings has 10min/2,5G. What "reasonable" size will be suitable for You?

comment:38 Changed 10 months ago by John Patrick Poet <jpoet@…>

In efdff1ba50c1ad412b4417ffc4a1d0de07b75395/mythtv:

H264Parser: Fix decoding of SPS

This also tightens up our implementation against the latest H.264 spec.

A BIG thank you to blm-ubunet@… for taking the time to read
the spec and compare it to our implementation.

Refs #11435

comment:39 Changed 10 months ago by John Patrick Poet <jpoet@…>

In f5c2875ec2c95c3cb3c695cdbd70fc63fceb6942/mythtv:

H264Parser: Fix decoding of SPS

This also tightens up our implementation against the latest H.264 spec.

A BIG thank you to blm-ubunet@… for taking the time to read
the spec and compare it to our implementation.

Refs #11435
(cherry picked from commit efdff1ba50c1ad412b4417ffc4a1d0de07b75395)

comment:40 Changed 10 months ago by jpoet

I believe I have found the root of the problem reported. Using the sample that warpme provided, I determined that the reason the keyframe offsets where off, is because we were failing to flush the payload buffer whenever a new payload started.

I am attaching a patch which does that just for completeness, but I will likely go ahead and commit this fix within the next day...

Changed 10 months ago by jpoet

Flush payload buffer at start each new payload - 0.26 version

Changed 10 months ago by jpoet

Flush payload buffer whenever a new payload starts

comment:41 Changed 10 months ago by John Poet <jpoet@…>

  • Resolution set to fixed
  • Status changed from accepted to closed

In 09b787346e5de8809b3905e64c1887dd273a860e/mythtv:

dtvrecorder: Flush the payload buffer whenever a new payload starts.

We start buffering at the beginning of each payload, and don't write out the
data until we know if this payload has a keyframe. This is so a new file
(for back to back recordings) would start on a keyframe.

Further, the keyframe offset recorded in the DB, is the offset to the
beginning of the payload with the keyframe. Or at least it was supposed to
be. Since we were not actually flushing any data currently in the buffer at
the start of a payload, that offset could be pointing to a completely
different payload!

Fixes #11435

comment:42 Changed 10 months ago by jpoet

  • Milestone changed from unknown to 0.27
  • Version changed from 0.26-fixes to Master Head

comment:43 Changed 10 months ago by blm_ubunet@…

My patch(s) also fixed the buffer offset problem in dtvrecorder.cpp.

HD-PVR:
H264Parser.cpp correctly identifies actual IDR frames for HD-PVR & my later patch accidentally disabled the "all I frames as keyframes" override.

The identified IDR frames match with ffprobe & avidemux.
I have also used Elecard StreamEye? (demo) analyser to inspect streams.

The original HD-PVR f/w produced non-compliant streams described as "No IDR, seekable I frame with no SEI recovery point messages.
The "use_I_forKeyframes" function call (from mpegrecorder.cpp) sets "I_is_keyframe=true" for HD-PVR recordings. This then causes all I frames to be identified keyframes.
I imagine this hack was needed to support the original HD-PVR streams.

The HD-PVR recording samples I have, use AVC main@L4.0 for 720p60 with an I frame every 28 frames with every 4th I frame as IDR. For IDR nal, the SEI recovery count is set correct (==0) & exact_match==1.

So for correct keyframe detection (in HD-PVR) needs I_is_keyframe=false.
The non-IDR I frames do seem to be seekable so perhaps the I frames positions also need to be stored into the seektable ( but not as keyframes).

This keyframe error would explain the 0 to 2 sec position errors that have plagued the "lossless_cut" script.

Thanks.

comment:44 Changed 10 months ago by blm-ubunet@…

Ha..from some digging in the archives..
http://www.gossamer-threads.com/lists/mythtv/commits/374997?search_string=hd-pvr;#374997
It seems you know all about this..

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'new'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.