[vdr] Recording does not stop
brian
Brian_Dorling at t-online.de
Fri Jun 8 12:39:32 CEST 2012
On 06/08/2012 11:45 AM, Klaus Schmidinger wrote:
> On 08.06.2012 08:39, brian wrote:
>> On 05/18/2012 05:04 PM, Klaus Schmidinger wrote:
>>> On 18.05.2012 15:32, brian wrote:
>>>> On 05/18/2012 10:04 AM, Klaus Schmidinger wrote:
>>>>> On 18.05.2012 09:49, brian wrote:
>>>>>> On 05/01/2012 01:28 PM, Klaus Schmidinger wrote:
>>>>>>> On 01.05.2012 13:07, brian wrote:
>>>>>>>> On 05/01/2012 11:54 AM, Klaus Schmidinger wrote:
>>>>>>>>> On 01.05.2012 07:50, brian wrote:
>>>>>>>>>> Hi,
>>>>>>>>>> doing some pretty heavy testing of VDR 1.7.21 as part of
>>>>>>>>>> gen2vdr V3 and have now twice had the case
>>>>>>>>>> that a recording did not end. Supposed to end at 23:10
>>>>>>>>>> yesterday, still going strong at 06:00 this
>>>>>>>>>> morning. Can't find anything in the history file of VDR that
>>>>>>>>>> this is a know problem and has been fixed in
>>>>>>>>>> later versions.
>>>>>>>>>> Here is some of the log:
>>>>>>>>>>
>>>>>>>>>> Apr 30 21:59:00 [vdr] [2496] timer 1 (1 2159-2310 'Silent
>>>>>>>>>> Witness') start
>>>>>>>>>> Apr 30 21:59:00 [vdr] [2496] Title: 'Silent Witness'
>>>>>>>>>> Subtitle: 'Fear - Part Two'
>>>>>>>>>> Apr 30 21:59:00 [vdr] [2496] executing '/tmp/vdr/vdr_record
>>>>>>>>>> before "/video/Silent_Witness/2012-04-30.21.59.1-0.rec"'
>>>>>>>>>> Apr 30 21:59:00 [logger] BJD g2v_record.sh Called: 0 =
>>>>>>>>>> /tmp/vdr/vdr_record
>>>>>>>>>> Apr 30 21:59:00 [logger] 2012-04-30 21:59 /tmp/vdr/vdr_record
>>>>>>>>>> before /video/Silent_Witness/2012-04-30.21.59.1-0.rec
>>>>>>>>>> Apr 30 21:59:00 [logger] /usr/sbin/mailtext: Started Start
>>>>>>>>>> 2012-04-30 21.59 Silent Witness.
>>>>>>>>>> Apr 30 21:59:00 [logger] [g2v_rec_msg.sh] Silent Witness:
>>>>>>>>>> Warte auf Verzeichnis
>>>>>>>>>> - Last output repeated 2 times -
>>>>>>>>>> Apr 30 21:59:01 [sSMTP] Sent mail for
>>>>>>>>>> Brian_dorling at t-online.de (221 2.0.0 fwd22.t-online.de
>>>>>>>>>> closing. / Verbindung wird getrennt.) u
>>>>>>>>>> Apr 30 21:59:01 [logger] Apr 30 21:59:01 gen2vdr
>>>>>>>>>> sendemail[3863]: Email was sent successfully!
>>>>>>>>>> Apr 30 21:59:01 [logger] /usr/sbin/mailtext: Done
>>>>>>>>>> Apr 30 21:59:01 [vdr] [2496] record
>>>>>>>>>> /video/Silent_Witness/2012-04-30.21.59.1-0.rec
>>>>>>>>>> Apr 30 21:59:01 [vdr] [2496] creating directory
>>>>>>>>>> /video/Silent_Witness/2012-04-30.21.59.1-0.rec
>>>>>>>>>> Apr 30 21:59:02 [vdr] [2496] recording to
>>>>>>>>>> '/video/Silent_Witness/2012-04-30.21.59.1-0.rec/00001.ts'
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Doesn't seem to try to end at 23:10
>>>>>>>>>>
>>>>>>>>>> Apr 30 22:59:50 [vdr] [2738] channel 1 (BBC 1 London) event
>>>>>>>>>> Mon 30.04.2012 23:00-23:25 'BBC News' status 4
>>>>>>>>>> Apr 30 23:00:01 [cron] (root) CMD (rm -f
>>>>>>>>>> /var/spool/cron/lastrun/cron.hourly)
>>>>>>>>>> Apr 30 23:01:59 [vdr] [2734] read incomplete section - len =
>>>>>>>>>> 428, r = 214
>>>>>>>>>> Apr 30 23:12:36 [ntpd] peer 213.198.55.2 now valid
>>>>>>>>>> Apr 30 23:12:39 [ntpd] peer 129.70.132.36 now valid
>>>>>>>>>> Apr 30 23:12:48 [ntpd] peer 178.63.99.230 now valid
>>>>>>>>>> Apr 30 23:14:41 [vdr] [3935] recording to
>>>>>>>>>> '/video/Silent_Witness/2012-04-30.21.59.1-0.rec/00002.ts'
>>>>>>>>>> Apr 30 23:18:11 [kernel] lirc_serial: ignoring spike: 1 1
>>>>>>>>>> 4f9f0193 4f9f0190 87401 aa74b
>>>>>>>>>> Apr 30 23:20:41 [ntpd] skew change -36.162 exceeds limit
>>>>>>>>>> Apr 30 23:20:41 [ntpd] clock is now synced
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Still going strong:
>>>>>>>>>>
>>>>>>>>>> May 01 00:07:37 [vdr] [2738] channel 1 (BBC 1 London) event
>>>>>>>>>> Tue 01.05.2012 00:05-00:35 'Late Kick Off' status 4
>>>>>>>>>> May 01 00:19:30 [vdr] [3935] recording to
>>>>>>>>>> '/video/Silent_Witness/2012-04-30.21.59.1-0.rec/00003.ts'
>>>>>>>>>> May 01 00:24:40 [vdr] [2779] TVTV: Packed String:
>>>>>>>>>> DKVxHLuoiXDxsDu98Eavvg==
>>>>>>>>>> ....
>>>>>>>>>> May 01 01:23:04 [vdr] [3935] recording to
>>>>>>>>>> '/video/Silent_Witness/2012-04-30.21.59.1-0.rec/00004.ts'
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Deleted the timer manually:
>>>>>>>>>>
>>>>>>>>>> May 01 06:37:39 [vdr] [2496] timer 1 (1 2159-2310 'Silent
>>>>>>>>>> Witness') stop
>>>>>>>>>> May 01 06:37:39 [vdr] [2496] executing '/tmp/vdr/vdr_record
>>>>>>>>>> after "/video/Silent_Witness/2012-04-30.21.59.1-0.rec"'
>>>>>>>>>> May 01 06:37:39 [logger] BJD g2v_record.sh Called: 0 =
>>>>>>>>>> /tmp/vdr/vdr_record
>>>>>>>>>> May 01 06:37:39 [logger] 2012-05-01 06:37 /tmp/vdr/vdr_record
>>>>>>>>>> after /video/Silent_Witness/2012-04-30.21.59.1-0.rec
>>>>>>>>>> May 01 06:37:39 [logger] /usr/sbin/mailtext: Started End
>>>>>>>>>> 2012-04-30 21.59 Silent Witness.
>>>>>>>>>> May 01 06:37:39 [vdr] [3939] TS buffer on device 3 thread
>>>>>>>>>> ended (pid=2496, tid=3939)
>>>>>>>>>> May 01 06:37:39 [vdr] [3936] buffer stats: 95316 (4%) used
>>>>>>>>>> May 01 06:37:39 [vdr] [3936] receiver on device 3 thread
>>>>>>>>>> ended (pid=2496, tid=3936)
>>>>>>>>>>
>>>>>>>>>> Any ideas?
>>>>>>>>>
>>>>>>>>> Did this happen only once, or is it reproducible?
>>>>>>>>>
>>>>>>>>> Is this "plain vanilla" VDR or are there any patches involved.
>>>>>>>>> I never had this problem with plain vanilla VDR.
>>>>>>>>>
>>>>>>>>> Klaus
>>>>>>>>>
>>>>>>>> Moin,
>>>>>>>>
>>>>>>>> second time now. Its the standard gen2vdr distribution so
>>>>>>>> various patches and plugins I guess.
>>>>>>>>
>>>>>>>> I am not trying to use VPS, can I rule that out due to the
>>>>>>>> messages shown?
>>>>>>>
>>>>>>> Since there is no VPS keyword in the timer line at
>>>>>>>
>>>>>>> Apr 30 21:59:00 [vdr] [2496] timer 1 (1 2159-2310 'Silent
>>>>>>> Witness') start
>>>>>>>
>>>>>>> it's safe to assume that VPS is not being used.
>>>>>>>
>>>>>>>>> >Apr 30 23:01:59 [vdr] [2734] read incomplete section - len =
>>>>>>>>> 428, r = 214
>>>>>>>>
>>>>>>>> Is the above message important?
>>>>>>>
>>>>>>> No.
>>>>>>>
>>>>>>>> I'll try to strip it down then and see if it reoccurs.
>>>>>>>
>>>>>>> Try to get rid of as many patches as possible (preferably all of
>>>>>>> them ;-).
>>>>>>> And use only the plugin necessary for output, nothing else.
>>>>>>>
>>>>>>> Klaus
>>>>>>>
>>>>>>>
>>>>>> Hi Klaus,
>>>>>>
>>>>>> without plugins up till now no problems till yesterday evening.
>>>>>> The VDR is still up, but not recording anything,
>>>>>> no disk activity at all.
>>>>>>
>>>>>> May 17 21:59:03 [vdr] [2513] SVDRP message: 'Aufnahme: Close~Lost
>>>>>> in Translation'
>>>>>> May 17 21:59:04 [vdr] [2513] info: Aufnahme: Close~Lost in
>>>>>> Translation
>>>>>> May 17 21:59:04 [vdr] [2513] closing SVDRP connection
>>>>>> May 17 21:59:06 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated twice -
>>>>>> May 17 21:59:08 [vdr] [4213] buffer usage: 70% (tid=4212)
>>>>>> May 17 21:59:08 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> May 17 21:59:08 [vdr] [4213] buffer usage: 80% (tid=4212)
>>>>>> May 17 21:59:08 [vdr] [4213] buffer usage: 90% (tid=4212)
>>>>>> May 17 21:59:09 [vdr] [4213] buffer usage: 100% (tid=4212)
>>>>>> May 17 21:59:09 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 4 times -
>>>>>> May 17 21:59:13 [vdr] [4218] video directory scanner thread
>>>>>> started (pid=2513, tid=4218)
>>>>>> May 17 21:59:13 [vdr] [4219] video directory scanner thread
>>>>>> started (pid=2513, tid=4219)
>>>>>> May 17 21:59:13 [vdr] [4219] video directory scanner thread ended
>>>>>> (pid=2513, tid=4219)
>>>>>> May 17 21:59:13 [vdr] [4218] video directory scanner thread ended
>>>>>> (pid=2513, tid=4218)
>>>>>>
>>>>>>
>>>>>> Log is full with the following messages:
>>>>>>
>>>>>> May 17 21:59:14 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated twice -
>>>>>> May 17 21:59:15 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 21:59:16 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 8 times -
>>>>>> May 17 21:59:24 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 21:59:25 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>>
>>>>>> Which I guess means that VDR never got around to checking that
>>>>>> the timer had finished. The program was 1hour long with
>>>>>> a 20 minute buffer added to the end. Log around the time it
>>>>>> should have ended shows nothing.
>>>>>>
>>>>>> May 17 23:19:37 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:38 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 3 times -
>>>>>> May 17 23:19:41 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:42 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 3 times -
>>>>>> May 17 23:19:45 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:46 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 2 times -
>>>>>> May 17 23:19:48 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:49 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 3 times -
>>>>>> May 17 23:19:52 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:53 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 5 times -
>>>>>> May 17 23:19:58 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:19:59 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 5 times -
>>>>>> May 17 23:20:04 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:20:05 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 4 times -
>>>>>> May 17 23:20:09 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:20:11 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 4 times -
>>>>>> May 17 23:20:15 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:20:16 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 4 times -
>>>>>> May 17 23:20:20 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:20:21 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>> - Last output repeated 3 times -
>>>>>> May 17 23:20:24 [vdr] [4213] ERROR: driver buffer overflow on
>>>>>> device 2
>>>>>> May 17 23:20:25 [vdr] [4212] ERROR: TS packet not accepted in
>>>>>> Transfer Mode
>>>>>>
>>>>>>
>>>>>> Emergency Exit = 1 is set in the config.
>>>>>>
>>>>>> Any ideas?
>>>>>
>>>>> These log messages indicate that the output device is in trouble and
>>>>> doesn't accept data any more. Since this is happening in transfer
>>>>> mode
>>>>> (i.e. "live"), there is no reason for an "emergency exit". Either
>>>>> switch
>>>>> to a different channel (which will restart the transfer mode and
>>>>> probably
>>>>> reinitialize the output device) or manually restart VDR.
>>>>>
>>>>> Klaus
>>>>>
>>>> Hi Klaus,
>>>>
>>>> I did restart VDR OK. But, same as last time, hours later the VDR
>>>> is still running
>>>> and I assume would keep on running for ever producing these
>>>> messages, as it seems
>>>> to have missed the end of the recording, which doesn't seem right
>>>> somehow.
>>>
>>> I don't see how VDR could "miss" the end of a recording (assuming it
>>> is not a VPS
>>> recording). I guess you'll need to add some debug output to
>>> cTimer::Matches() in
>>> order to find out what's going wrong there.
>>>
>>>> There is no live viewing on this VDR, any idea why it was in
>>>> transfer mode?
>>>
>>> Maybe earlier entries in your log file can answer that question.
>>> Look for a message that indicates the start of the transfer mode
>>> thread.
>>>
>>> Klaus
>>>
>>>
>> Hi Klaus,
>> I added some debugging statements to where you suggested, but I am
>> ashamed to say that I can't
>> properly follow the logic, even when it works correctly. Could you
>> please give me some simple
>> tips?
>
> You could try this:
>
> --- timers.c 2012/06/03 13:04:23 2.10
> +++ timers.c 2012/06/08 09:43:49
> @@ -443,6 +443,7 @@
> }
> }
> }
> + if (HasFlags(tfRecording)) dsyslog("timer data: %ld %ld %d %ld",
> startTime, t, Margin, stopTime);//XXX
> return startTime <= t + Margin && t < stopTime; // must stop
> *before* stopTime to allow adjacent timers
> }
> return false;
>
> With this any running timer will continuously log its data, so we
> should be
> able to see what's going on when the stop time passes by and the timer
> doesn't
> stop recording.
>
> Klaus
>
> _______________________________________________
> vdr mailing list
> vdr at linuxtv.org
> http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
>
Hmm,
changed it a bit to not log so many messages:
Jun 8 12:35:40 [vdr] [8428] Within 5 MInutes of end. timer data:
1339149540 1339151740 0 1339151760
- Last output repeated 13 times -
Jun 8 12:35:41 [vdr] [8428] Within 5 MInutes of end. timer data:
1339149540 1339151741 0 1339151760
- Last output repeated twice -
Jun 8 12:35:41 [vdr] [8428] closing SVDRP connection
Jun 8 12:35:41 [vdr] [8428] Within 5 MInutes of end. timer data:
1339149540 1339151741 0 1339151760
So according to the first line ::Matches was called 14 times within the
same second. Is that correct?
Up till now I only saw the messages once a second.
Cheers Brian
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.linuxtv.org/pipermail/vdr/attachments/20120608/f8318b94/attachment-0001.html>
More information about the vdr
mailing list