[mythtv-users] silence detection blocks jobqueue [ mythcommflag; silence.py ]
Stefan Pappalardo
stefan.pappalardo at gmx.de
Mon Oct 20 13:33:18 UTC 2014
Am 20.10.2014 um 14:42 schrieb Mark Perkins:
>
>
>> On 20 Oct 2014, at 10:30 pm, "Stefan Pappalardo" <stefan.pappalardo at gmx.de> wrote:
>>
>>> Am 20.10.2014 um 13:28 schrieb Roger Siddons:
>>>> On Mon, 20 Oct 2014 11:30:49 +0100, Stefan Pappalardo <stefan.pappalardo at gmx.de> wrote:
>>>>
>>>>> Am 18.10.2014 um 17:59 schrieb Roger Siddons:
>>>>> Even though it's not detecting anything, it may take a while (3-4 minutes) to process the recording if it's long - are you allowing it long enough to finish before killing it ?
>>>>
>>>> In most cases I got aware of the job-qeue-blocking a day or two later, quite enough time to finish.
>>>>
>>>> Stefan Pappalardo
>>>
>>> That's interesting. Maybe the mythffmpeg is crashing, in which case the script may well hang.
>>>
>>> Another test is to try it in a terminal with a very low audio threshold, ie:
>>>
>>> silence.py 14065 --loglevel debug --preset -50
>>>
>>> That should produce lots of detections/logging, so we can see if it starts or how far it gets.
>>>
>>> Could you also post the result of "mythffmpeg -i" on the problem recording, probably:
>>>
>>> mythffmpeg -i <path>/1043_20141015125000.mpg
>>> _______________________________________________
>>> mythtv-users mailing list
>>> mythtv-users at mythtv.org
>>> http://www.mythtv.org/mailman/listinfo/mythtv-users
>>> http://wiki.mythtv.org/Mailing_List_etiquette
>>> MythTV Forums: https://forum.mythtv.org
>>
>> Here you are...
>>
>> $ silence.py --chanid 1043 --starttime 20141015145000 --loglevel debug --preset -50
>> 2014-10-20 13:55:51.154416 D [9302] Python Database Connection Trying database credentials from: /home/sjuk/config.xml
>> 2014-10-20 13:55:51.184662 I [9302] mythcommflag:
>> 2014-10-20 13:55:51.191888 I [9302] mythcommflag: Seeking chanid 1043, starttime 2014-10-15 14:50:00+02:00
>> 2014-10-20 13:55:51.213598 I [9302] mythcommflag: Processing: Cinema24, 2014-10-15 14:50:00+02:00, "Keinohrhase und Zweiohrküken - Komödie"
>> 2014-10-20 13:55:51.218261 D [9302] mythcommflag: Parsing presets from "-50"
>> 2014-10-20 13:55:51.232856 D [9302] mythcommflag: Threshold=-50.0, MinQuiet=0.16, MinDetect=6.0, MinLength=120.0, MaxSep=120.0, Pad=0.48
>> 2014-10-20 13:55:51.233584 D [9302] mythcommflag: Frame rate is 25.00, Detecting silences below 6790940 that last for at least 4 frames
>> 2014-10-20 13:55:51.234180 D [9302] mythcommflag: Clusters are composed of a minimum of 6 silences closer than 3000 frames and must be
>> 2014-10-20 13:55:51.234787 D [9302] mythcommflag: longer than 3000 frames in total. Cuts will be padded by 12 frames
>> 2014-10-20 13:55:51.235438 D [9302] mythcommflag: < preroll, > postroll, - advert, ? too few silences, # too short, = comm flagged
>> 2014-10-20 13:55:51.236101 I [9302] mythcommflag: Start - End Start - End Duration Interval Level/Count
>> 2014-10-20 13:55:51.236738 I [9302] mythcommflag: frame - frame (mmm:ss-mmm:ss) frame (mm:ss.s) frame (mmm:ss)
>> 2014-10-20 13:55:51.296288 D [9302] mythcommflag: Silence 1- 12 ( 0:00- 0:00), 12 ( 0:00.5), 0 ( 0:00), [4120003]
>> 2014-10-20 13:55:51.301237 D [9302] mythcommflag: Silence 28- 32 ( 0:01- 0:01), 5 ( 0:00.2), 17 ( 0:01), [5905987]
>> 2014-10-20 13:55:51.306109 D [9302] mythcommflag: Silence 46- 51 ( 0:02- 0:02), 6 ( 0:00.2), 15 ( 0:01), [5851353]
>> 2014-10-20 13:55:51.316041 D [9302] mythcommflag: Silence 85- 88 ( 0:03- 0:04), 4 ( 0:00.2), 35 ( 0:01), [6247750]
>> 2014-10-20 13:55:51.332801 D [9302] mythcommflag: Silence 92- 149 ( 0:04- 0:06), 58 ( 0:02.3), 5 ( 0:00), [4170067]
>> 2014-10-20 13:55:51.389306 D [9302] mythcommflag: Silence 225- 279 ( 0:09- 0:11), 55 ( 0:02.2), 77 ( 0:03), [3871374]
>> 2014-10-20 13:55:51.392573 D [9302] mythcommflag: Silence 281- 285 ( 0:11- 0:11), 5 ( 0:00.2), 3 ( 0:00), [6057235]
>> 2014-10-20 13:55:51.769554 D [9302] mythcommflag: Silence 1397- 1400 ( 0:56- 0:56), 4 ( 0:00.2), 1113 ( 0:45), [6645606]
>> 2014-10-20 13:55:51.771487 D [9302] mythcommflag: Silence 1402- 1405 ( 0:56- 0:56), 4 ( 0:00.2), 3 ( 0:00), [5851287]
>> 2014-10-20 13:55:51.934125 D [9302] mythcommflag: Silence 1832- 1835 ( 1:13- 1:13), 4 ( 0:00.2), 428 ( 0:17), [6458509]
>> 2014-10-20 13:55:51.937958 D [9302] mythcommflag: Silence 1839- 1846 ( 1:14- 1:14), 8 ( 0:00.3), 5 ( 0:00), [4693672]
>> 2014-10-20 13:55:52.615999 D [9302] mythcommflag: Silence 3948- 3973 ( 2:38- 2:39), 26 ( 0:01.0), 2103 ( 1:24), [3553854]
>
> Did it stop here by itself (ie 2:39 into the recording)? Or did it hang? Or something else?
The script stoped by itself and remains (hangs) there. I had to send ctrl-c to stop it (after waiting for a while; nothing more in the log.
When watching the recording there is nothing unusual (for me) from 0:00 to 03:00. Here the output of the logs (hint: I paused watching while writing some words into this mail)...
mythfrontend.log:
Oct 20 15:03:19 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext bonjourregister.cpp:115 (BonjourCallback) Bonjour: Service registration complete: name 'Mythfrontend on asterix' type '_mythfro
Oct 20 15:04:03 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:1063 (TV) TV: Creating TV object
Oct 20 15:04:03 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:1280 (Init) TV: Created TvPlayWindow.
Oct 20 15:04:03 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:2225 (HandleStateChange) TV: Attempting to change from None to WatchingPreRecorded
Oct 20 15:04:03 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext audioplayer.cpp:164 (ReinitAudio) AudioPlayer: Enabling Audio
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2141 (ScanStreams) AFD: codec MP2 has 2 channels
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0xbe9f2e0, id(MP2) type(Audio)
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2141 (ScanStreams) AFD: codec MP2 has 2 channels
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0xbe9fb40, id(MP2) type(Audio)
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2141 (ScanStreams) AFD: codec AC3 has 6 channels
Oct 20 15:04:04 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0xbea05c0, id(AC3) type(Audio)
Oct 20 15:04:05 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:1751 (CheckHardwareSupport) VDPAU: Version 1
Oct 20 15:04:05 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:1762 (CheckHardwareSupport) VDPAU: Information NVIDIA VDPAU Driver Shared Library 331.38 Wed Jan 8 19:1
Oct 20 15:04:05 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0x3a93540, id(MPEG2VIDEO) type(Video)
Oct 20 15:04:05 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext audio/audiooutputbase.cpp:792 (Reconfigure) AOBase: Opening audio device 'PulseAudio:default' ch 2(6) sr 48000 sf 32 bit floati
Oct 20 15:04:05 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL painter cache.
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:1717 (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:424 (Create) VDPAU: Created VDPAU render device 1920x1080
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:526 (CheckExtraAudioDecode) Player(0): Forcing decode extra audio option on (Video method requires it).
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: E CoreContext filtermanager.cpp:243 (LoadFilters) FilterManager: Failed to load filter 'colorspace', no such filter exists
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythplayer.cpp:1783 (InitAVSync) Player(0): Video timing method: USleep with busy wait
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:5621 (StartPlayer) TV: Created player.
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:2485 (HandleStateChange) TV: Changing from None to WatchingPreRecorded
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:2576 (HandleStateChange) TV: Main UI disabled.
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:412 (StartTV) TV: Entering main playback loop.
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext screensaver-x11.cpp:149 (DisableDPMS) ScreenSaverX11Private: DPMS Deactivated 1
Oct 20 15:04:06 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:610 (CheckOutputSurfaces) VDPAU: Added 2 output surfaces (total 4, max 4)
Oct 20 15:04:36 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.00 Mean: 40004 Std.Dev: 9334 CPUs: 100% 100%
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:2141 (ScanStreams) AFD: codec MP3 has 0 channels
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0x7f8e68001c00, id(MP3) type(Audio)
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:2141 (ScanStreams) AFD: codec AC3 has 0 channels
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0x7f8e680b9240, id(AC3) type(Audio)
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: W Decoder mythpainter.cpp:36 (Teardown) MythPainter: 30 images not yet de-allocated.
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythpainter_vdpau.cpp:108 (ClearCache) VDPAU Painter: Clearing VDPAU painter cache.
Oct 20 15:07:08 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL painter cache.
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythrender_vdpau.cpp:1717 (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythrender_vdpau.cpp:424 (Create) VDPAU: Created VDPAU render device 1920x1080
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N Decoder mythplayer.cpp:526 (CheckExtraAudioDecode) Player(0): Forcing decode extra audio option on (Video method requires it).
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: E Decoder filtermanager.cpp:243 (LoadFilters) FilterManager: Failed to load filter 'colorspace', no such filter exists
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:2632 (OpenAVCodec) AFD: Opened codec 0x7f8e68002800, id(MPEG2VIDEO) type(Video)
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 192ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: E thread_unknown audio/audiooutputpulse.cpp:666 (BufferFlowCallback) PulseAudio: stream buffer under flow
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 294ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 398ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 500ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 603ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 705ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 805ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 909ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 1011ms for video buffers AAAAAAAAAAAAAA
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N Decoder audioplayer.cpp:164 (ReinitAudio) AudioPlayer: Enabling Audio
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: E Decoder avformatdecoder.cpp:3604 (ProcessVideoPacket) AFD: Unknown decoding error
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythpainter_vdpau.cpp:108 (ClearCache) VDPAU Painter: Clearing VDPAU painter cache.
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 1113ms for video buffers
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2148 (PrebufferEnoughFrames) Player(0): Timed out waiting for frames, and#012#011#011#011there are not enough fr
Oct 20 15:07:09 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL painter cache.
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythrender_vdpau.cpp:1717 (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I Decoder mythrender_vdpau.cpp:424 (Create) VDPAU: Created VDPAU render device 1920x1080
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: N Decoder mythplayer.cpp:526 (CheckExtraAudioDecode) Player(0): Forcing decode extra audio option on (Video method requires it).
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: E Decoder filtermanager.cpp:243 (LoadFilters) FilterManager: Failed to load filter 'colorspace', no such filter exists
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: N CoreContext mythplayer.cpp:2133 (PrebufferEnoughFrames) Player(0): Waited 1266ms for video buffers LAAAAAAAAAAAAA
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I Decoder avformatdecoder.cpp:4747 (ProcessAudioPacket) AFD: Audio stream changed
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I Decoder audio/audiooutputbase.cpp:792 (Reconfigure) AOBase: Opening audio device 'PulseAudio:default' ch 2(2) sr 48000 sf 32 bit floating p
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythrender_vdpau.cpp:610 (CheckOutputSurfaces) VDPAU: Added 2 output surfaces (total 4, max 4)
Oct 20 15:07:10 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 0.16 Mean: 6119875 Std.Dev: 30127512 CPUs: 18% 18%
Oct 20 15:07:11 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.01 Mean: 39979 Std.Dev: 181 CPUs: 20% 19%
Oct 20 15:07:12 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.02 Mean: 39971 Std.Dev: 270 CPUs: 22% 21%
Oct 20 15:07:13 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.01 Mean: 39977 Std.Dev: 282 CPUs: 23% 20%
Oct 20 15:07:14 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.02 Mean: 39965 Std.Dev: 932 CPUs: 21% 22%
Oct 20 15:07:15 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext jitterometer.cpp:119 (RecordEndTime) Player(0): FPS: 25.01 Mean: 39988 Std.Dev: 298 CPUs: 22% 21%
Oct 20 15:07:23 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext screensaver-x11.cpp:161 (RestoreDPMS) ScreenSaverX11Private: DPMS Reactivated 1
Oct 20 15:21:39 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:2225 (HandleStateChange) TV: Attempting to change from WatchingPreRecorded to None
Oct 20 15:21:39 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext mythpainter_vdpau.cpp:108 (ClearCache) VDPAU Painter: Clearing VDPAU painter cache.
Oct 20 15:21:39 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:2485 (HandleStateChange) TV: Changing from WatchingPreRecorded to None
Oct 20 15:21:39 asterix mythfrontend.real: mythfrontend[13385]: I CoreContext tv_play.cpp:414 (StartTV) TV: Exiting main playback loop.
mythbackend.log:
Oct 20 15:03:33 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1563 (HandleAnnounce) adding: asterix as a remote file transfer
Oct 20 15:03:58 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Playback
Oct 20 15:03:58 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: asterix as a client (events: 0)
Oct 20 15:03:58 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1561 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Oct 20 15:03:58 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1563 (HandleAnnounce) adding: asterix as a remote file transfer
Oct 20 15:04:03 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Playback
Oct 20 15:04:03 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: asterix as a client (events: 0)
Oct 20 15:04:03 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1561 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Oct 20 15:04:03 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1563 (HandleAnnounce) adding: asterix as a remote file transfer
Oct 20 15:06:00 obelix mythbackend: mythbackend[3062]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 10.0 GB w/freq: 7 min
Oct 20 15:06:01 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 24 2014-10-20T14:00:00Z EITScanner
Oct 20 15:06:01 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 310 items in 0.4 = 0.05 match + 0.00 check + 0.37 place
Oct 20 15:06:15 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 25 2014-10-23T23:35:00Z EITScanner
Oct 20 15:06:16 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 310 items in 0.4 = 0.05 match + 0.04 check + 0.34 place
Oct 20 15:07:29 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 25 2014-10-20T13:55:00Z EITScanner
Oct 20 15:07:29 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 310 items in 0.4 = 0.05 match + 0.01 check + 0.36 place
Oct 20 15:10:00 obelix mythbackend: mythbackend[3062]: I TVRecEvent tv_rec.cpp:1050 (HandleStateChange) TVRec[3]: Changing from RecordingOnly to None
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: E CoreContext mainserver.cpp:970 (customEvent) MainServer: PREVIEW_SUCCESS but no receivers.
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: I TVRecEvent recordinginfo.cpp:1075 (FinishedRecording) Finished recording Schloss Einstein - Erfurt: channel 29008
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: I CoreContext scheduler.cpp:704 (UpdateRecStatus) Updating status for "Schloss Einstein - Erfurt" on cardid 3 (Aufnehmen => Aufgenommen)
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for CHECK -3 1331 0 UpdateRecStatus2 | Schloss Einstein - Erfurt | | Aus Angst
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 309 items in 0.5 = 0.00 match + 0.00 check + 0.45 place
Oct 20 15:10:01 obelix mythbackend: mythbackend[3062]: I Metadata_14141 jobqueue.cpp:2156 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for "Schloss Einstein - Erfurt" recorded from channel 2
Oct 20 15:10:02 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor
Oct 20 15:10:02 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 0)
Oct 20 15:10:04 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Playback
Oct 20 15:10:04 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 0)
Oct 20 15:10:04 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor
Oct 20 15:10:04 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 1)
Oct 20 15:10:16 obelix mythbackend: mythbackend[3062]: I UserJob_14143 jobqueue.cpp:2409 (DoUserJobThread) JobQueue: Started Werbeerkennung (silence) for "Schloss Einstein - Erfurt" recorded from channel 2
Oct 20 15:10:17 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor
Oct 20 15:10:17 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 0)
Oct 20 15:10:18 obelix mythbackend: mythbackend[3062]: E EIT programdata.cpp:433 (GetMatch) Unexpected result: shows don't overlap#012#011 Der Burj Khalifa Dubai: 2014-10-26T01:55:00Z - 2014-10-26T0
Oct 20 15:11:01 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 0 0 2014-11-09T23:00:00Z EITScanner
Oct 20 15:11:07 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 309 items in 5.7 = 3.47 match + 1.91 check + 0.38 place
Oct 20 15:11:24 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 25 2014-10-27T13:10:00Z EITScanner
Oct 20 15:11:25 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 309 items in 0.5 = 0.05 match + 0.07 check + 0.36 place
Oct 20 15:11:40 obelix mythbackend: mythbackend[3062]: I UserJob_14143 jobqueue.cpp:2461 (DoUserJobThread) JobQueue: Finished Werbeerkennung (silence) for "Schloss Einstein - Erfurt" recorded from channel
Oct 20 15:13:00 obelix mythbackend: mythbackend[3062]: N Expire autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 10.0 GB w/freq: 14 min
Oct 20 15:14:54 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor
Oct 20 15:14:54 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 0)
Oct 20 15:16:03 obelix mythbackend: mythbackend[3062]: W TVRecEvent recorders/dvbchannel.cpp:386 (CheckOptions) DVBChan[3](/dev/dvb/adapter3/frontend0): Selected fec_inner parameter unsupported by this dri
Oct 20 15:16:03 obelix mythbackend: mythbackend[3062]: E TVRecEvent recorders/dvbchannel.cpp:1107 (GetUncorrectedBlockCount) DVBChan[3](/dev/dvb/adapter3/frontend0): Getting Frontend uncorrected block coun
Oct 20 15:16:03 obelix mythbackend: mythbackend[3062]: W TVRecEvent recorders/dvbsignalmonitor.cpp:97 (DVBSignalMonitor) DVBSigMon[3](/dev/dvb/adapter3/frontend0): Cannot count Uncorrected Blocks#012#011#0
Oct 20 15:16:05 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 25 2014-10-20T13:45:00Z EITScanner
Oct 20 15:16:05 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 309 items in 0.4 = 0.04 match + 0.01 check + 0.37 place
Oct 20 15:16:13 obelix mythbackend: mythbackend[3062]: E DVBRead mpeg/mpegstreamdata.cpp:365 (AssemblePSIP) MPEGStream[3](0x7f4ee044f358): Error: offset>181, pes length & current cannot be queried
Oct 20 15:16:53 obelix mythbackend: mythbackend[3062]: E DVBRead mpeg/mpegstreamdata.cpp:365 (AssemblePSIP) MPEGStream[3](0x7f4ee044f358): Error: offset>181, pes length & current cannot be queried
Oct 20 15:20:02 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1443 (HandleAnnounce) MainServer::ANN Monitor
Oct 20 15:20:02 obelix mythbackend: mythbackend[3062]: I ProcessRequest mainserver.cpp:1445 (HandleAnnounce) adding: obelix as a client (events: 0)
Oct 20 15:21:04 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 7 2014-11-16T23:15:00Z EITScanner
Oct 20 15:21:04 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 308 items in 0.5 = 0.03 match + 0.00 check + 0.42 place
Oct 20 15:21:05 obelix mythbackend: mythbackend[3062]: W TVRecEvent recorders/dvbchannel.cpp:386 (CheckOptions) DVBChan[3](/dev/dvb/adapter3/frontend0): Selected fec_inner parameter unsupported by this dri
Oct 20 15:21:06 obelix mythbackend: mythbackend[3062]: E TVRecEvent recorders/dvbchannel.cpp:1107 (GetUncorrectedBlockCount) DVBChan[3](/dev/dvb/adapter3/frontend0): Getting Frontend uncorrected block coun
Oct 20 15:21:06 obelix mythbackend: mythbackend[3062]: W TVRecEvent recorders/dvbsignalmonitor.cpp:97 (DVBSignalMonitor) DVBSigMon[3](/dev/dvb/adapter3/frontend0): Cannot count Uncorrected Blocks#012#011#0
Oct 20 15:21:15 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2139 (HandleReschedule) Reschedule requested for MATCH 0 1 25 2014-10-27T13:20:00Z EITScanner
Oct 20 15:21:15 obelix mythbackend: mythbackend[3062]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 308 items in 0.5 = 0.06 match + 0.07 check + 0.35 place
>
> According to the below it should be 1:39:55 long....
Yes it is.
>
> Do you have messages in your backend log about damaged recordings?
Perhaps there are. But not for this recording, as it is not in yellow font color (which is usually a hint for damaged recordings, I think).
>
>>
>> $ mythffmpeg -i 1043_20141015125000.mpg
>> ffmpeg version 1.2.7 Copyright (c) 2000-2014 the FFmpeg developers
>> built on Oct 17 2014 06:18:59 with gcc 4.8 (Ubuntu 4.8.2-19ubuntu1)
>> configuration: --compile-type=profile --prefix=/usr --runprefix=/usr --disable-mythlogserver --enable-crystalhd --enable-lirc --enable-audio-alsa --enable-audio-oss --enable-dvb --enable-ivtv --enable-firewire --enable-joystick-menu --with-bindings=perl --enable-ffmpeg-pthreads --enable-pic --perl-config-opts='INSTALLDIRS=vendor' --enable-libvpx --enable-sdl --enable-libmp3lame --enable-libx264 --enable-opengl-video --enable-vaapi --enable-vdpau
>> libavutil 52. 18.100 / 52. 18.100
>> libavcodec 54. 92.100 / 54. 92.100
>> libavformat 54. 63.104 / 54. 63.104
>> libavdevice 54. 3.103 / 54. 3.103
>> libavfilter 3. 42.103 / 3. 42.103
>> libswscale 2. 2.100 / 2. 2.100
>> libswresample 0. 17.102 / 0. 17.102
>> libpostproc 52. 2.100 / 52. 2.100
>> [mpegts @ 0x9caa20] max_analyze_duration 5000000 reached at 5000000 microseconds
>> [NULL @ 0x9cd920] start time is not set in estimate_timings_from_pts
>> [mpegts @ 0x9caa20] PES packet size mismatch
>> Last message repeated 1 times
>> Input #0, mpegts, from '1043_20141015125000.mpg':
>> Duration: 01:39:55.21, start: 89500.844867, bitrate: 4212 kb/s
>> Stream #0:0[0x20](deu): Subtitle: dvb_teletext
>> Stream #0:1[0x8ff]: Video: mpeg2video (Main), yuv420p, 720x576 [SAR 64:45 DAR 16:9], 25 fps, 25 tbr, 90k tbn, 50 tbc
>> Stream #0:2[0x900](deu): Audio: mp2, 48000 Hz, stereo, s16p, 192 kb/s
>> Stream #0:3[0x901](eng): Audio: mp2, 48000 Hz, stereo, s16p, 192 kb/s
>> Stream #0:4[0x903](deu): Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s
>> At least one output file must be specified
>>
>> --
>> Stefan Pappalardo
>> _______________________________________________
>> mythtv-users mailing list
>> mythtv-users at mythtv.org
>> http://www.mythtv.org/mailman/listinfo/mythtv-users
>> http://wiki.mythtv.org/Mailing_List_etiquette
>> MythTV Forums: https://forum.mythtv.org
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://www.mythtv.org/mailman/listinfo/mythtv-users
> http://wiki.mythtv.org/Mailing_List_etiquette
> MythTV Forums: https://forum.mythtv.org
>
--
Stefan Pappalardo
More information about the mythtv-users
mailing list