[vdr] Recording does not stop

brian Brian_Dorling at t-online.de
Fri Jun 8 08:39:18 CEST 2012


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
>
> _______________________________________________
> vdr mailing list
> vdr at linuxtv.org
> http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
>
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?

I have done some C programming in the past, but never any C++.

Cheers Brian














-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.linuxtv.org/pipermail/vdr/attachments/20120608/7c63b19b/attachment-0001.html>


More information about the vdr mailing list