[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