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@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?
Cheers Brian
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@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
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@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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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?
Apr 30 23:01:59 [vdr] [2734] read incomplete section - len = 428, r =
214
Is the above message important?
I'll try to strip it down then and see if it reoccurs.
Cheers Brian
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@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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
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@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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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?
Cheers Brian
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@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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
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@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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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
vdr mailing list vdr@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
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.
There is no live viewing on this VDR, any idea why it was in transfer mode?
Cheers Brian
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@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
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@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@linuxtv.org http://www.linuxtv.org/cgi-bin/mailman/listinfo/vdr
Hi,
VDR has two Cards:
May 17 21:54:30 [kernel] DDBridge driver detected: Digital Devices Cine S2 V6 DVB adapter May 17 21:54:30 [kernel] HW 00010007 FW 00010003 May 17 21:54:30 [kernel] Port 0 (TAB 1): DUAL DVB-S2 May 17 21:54:30 [kernel] Port 1 (TAB 2): NO MODULE May 17 21:54:30 [kernel] Port 2 (TAB 3): NO MODULE May 17 21:54:30 [kernel] DVB: registering new adapter (DDBridge) May 17 21:54:30 [kernel] LNBx2x attached on addr=a May 17 21:54:30 [kernel] stv6110x_attach: Attaching STV6110x May 17 21:54:30 [kernel] attach tuner input 0 adr 60 May 17 21:54:30 [kernel] DVB: registering adapter 0 frontend 0 (STV090x Multistandard)... May 17 21:54:30 [kernel] DVB: registering new adapter (DDBridge) May 17 21:54:30 [kernel] LNBx2x attached on addr=8 May 17 21:54:30 [kernel] stv6110x_attach: Attaching STV6110x May 17 21:54:30 [kernel] attach tuner input 1 adr 63 May 17 21:54:30 [kernel] DVB: registering adapter 1 frontend 0 (STV090x Multistandard)... May 17 21:54:30 [kernel] Linux media interface: v0.10 May 17 21:54:30 [kernel] Linux video capture interface: v2.00 May 17 21:54:30 [kernel] WARNING: You are using an experimental version of the media stack. May 17 21:54:30 [kernel] _As the driver is backported to an older kernel, it doesn't offer May 17 21:54:30 [kernel] _enough quality for its usage in production. May 17 21:54:30 [kernel] _Use it with care. May 17 21:54:30 [kernel] Latest git patches (needed if you report a bug tolinux-media@vger.kernel.org): May 17 21:54:30 [kernel] _2f4cf2c3a971c4d5154def8ef9ce4811d702852d [media] dib9000: release a lock on error May 17 21:54:30 [kernel] _4c4364e022f8422e602edbb97a2d873dc0b6c769 [media] mxl111sf: fix a couple precedence bugs May 17 21:54:30 [kernel] _446b792c6bd87de4565ba200b75a708b4c575a06 [media] media: DocBook: Fix trivial typo in Sub-device Interface May 17 21:54:30 [kernel] saa7146: register extension 'av7110' May 17 21:54:30 [kernel] av7110 0000:07:01.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 May 17 21:54:30 [kernel] saa7146: found saa7146 @ mem f943a000 (revision 1, irq 16) (0x13c2,0x0000) May 17 21:54:30 [kernel] DVB: registering new adapter (Technotrend/Hauppauge WinTV DVB-S rev1.X or Fujitsu Siemens DVB-C) May 17 21:54:30 [kernel] adapter has MAC addr = 00:d0:5c:01:02:fd May 17 21:54:30 [kernel] dvb-ttpci: gpioirq unknown type=0 len=0 May 17 21:54:30 [kernel] dvb-ttpci: info @ card 2: firm f0240009, rtsl b0250018, vid 71010068, app 8000261d May 17 21:54:30 [kernel] dvb-ttpci: firmware @ card 2 supports CI link layer interface May 17 21:54:30 [kernel] dvb-ttpci: adac type set to 0 @ card 2 May 17 21:54:30 [kernel] saa7146_vv: saa7146 (0): registered device video0 [v4l2] May 17 21:54:30 [kernel] saa7146_vv: saa7146 (0): registered device vbi0 [v4l2] May 17 21:54:30 [kernel] ves1x93: Detected ves1893a rev2 May 17 21:54:30 [kernel] DVB: registering adapter 2 frontend 0 (VLSI VES1x93 DVB-S)...
0/0 = Cine S2 1/0 = Cine S2 2/0 = FF
May 17 21:54:35 [vdr] [2513] setting primary device to 2
In case I need to watch this VDR.
May 17 21:54:37 [vdr] [2513] switching to channel 2 May 17 21:54:37 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 2: ProvidesChannel 2 on device 1. Priority is 0, hasPriority is 1 May 17 21:54:37 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: Request for channel 2 on device 3. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: ProvidesChannel 2 on device 2. Priority is 0, hasPriority is 1 May 17 21:54:37 [vdr] [2513] LNB 3: Request for channel 2 on device 3. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: Switching device 2 to channel 2 May 17 21:54:37 [vdr] [2513] LNB 3: Device check for channel 2 on device 2. OK May 17 21:54:37 [vdr] [2513] setting watchdog timer to 60 seconds May 17 21:54:37 [vdr] [2573] CAM 1: no module present May 17 21:54:37 [vdr] [2573] CAM 2: no module present May 17 21:54:37 [vdr] [2513] OSD size changed to 720x576 @ 1.06667 May 17 21:54:37 [vdr] [2560] video directory scanner thread ended (pid=2513, tid=2560)
May 17 21:54:37 [vdr] [2513] timer 2 (1 2159-2310 'Close') set to event Thu 17.05.2012 22:00-23:00 'New Tricks'
Times seem to be set OK. But Margin start = 1 and Margin stop = 2 on this VDR. No messages about stopping the recording around 23:02.
ay 17 21:58:06 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:58:06 [vdr] [2513] switching device 1 to channel 1 May 17 21:58:06 [vdr] [2513] LNB 2: Switching device 1 to channel 1 May 17 21:58:06 [vdr] [2513] LNB 2: Device check for channel 1 on device 1. OK May 17 21:59:00 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 2: ProvidesChannel 1 on device 1. Priority is 99, hasPriority is 1 May 17 21:59:00 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 3: Request for channel 1 on device 3. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 3: ProvidesChannel 1 on device 2. Priority is 99, hasPriority is 1 May 17 21:59:00 [vdr] [2513] LNB 3: Request for channel 1 on device 3. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] switching device 2 to channel 1 May 17 21:59:00 [vdr] [2513] LNB 3: Switching device 2 to channel 1 May 17 21:59:00 [vdr] [2513] LNB 3: Device check for channel 1 on device 2. OK May 17 21:59:00 [vdr] [2513] timer 2 (1 2159-2310 'Close') start May 17 21:59:00 [vdr] [2513] Title: 'New Tricks' Subtitle: 'Lost in Translation' May 17 21:59:00 [vdr] [2513] executing '/tmp/vdr/vdr_record before "/video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec"' May 17 21:59:00 [logger] BJD g2v_record.sh Called: 0 = /tmp/vdr/vdr_record May 17 21:59:00 [logger] 2012-05-17 21:59 /tmp/vdr/vdr_record before /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:00 [logger] /usr/sbin/mailtext: Started Start 2012-05-17 21.59 Lost in Translation. May 17 21:59:00 [logger] [g2v_rec_msg.sh] Close~Lost in Translation: Warte auf Verzeichnis - Last output repeated 3 times - May 17 21:59:02 [sSMTP] Sent mail forBrian_dorling@t-online.de (221 2.0.0 fwd19.t-online.de closing. / Verbindung wird getrennt.) u id=0 username=root outbytes=436 May 17 21:59:02 [logger] May 17 21:59:02 gen2vdr sendemail[3873]: Email was sent successfully! May 17 21:59:02 [logger] /usr/sbin/mailtext: Done May 17 21:59:02 [vdr] [2513] record /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:02 [vdr] [2513] creating directory /video/Close/Lost_in_Translation May 17 21:59:02 [vdr] [2513] creating directory /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:02 [vdr] [2513] recording to '/video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec/00001.ts' May 17 21:59:02 [vdr] [3992] recording thread started (pid=2513, tid=3992) May 17 21:59:02 [vdr] [3993] receiver on device 3 thread started (pid=2513, tid=3993) May 17 21:59:02 [vdr] [3995] TS buffer on device 3 thread started (pid=2513, tid=3995) May 17 21:59:02 [logger] [g2v_rec_msg.sh] Aufnahme: Close~Lost in Translation May 17 21:59:03 [vdr] [2513] switching to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:59:03 [vdr] [2513] LNB 2: ProvidesChannel 2 on device 1. Priority is 0, hasPriority is 1 May 17 21:59:03 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:59:03 [vdr] [2513] LNB 3: ProvidesChannel 2 on device 2. Priority is 0, hasPriority is 0 May 17 21:59:03 [vdr] [2513] LNB 3: Switching device 2 to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Switching device 1 to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Device check for channel 2 on device 1. OK May 17 21:59:03 [vdr] [4212] receiver on device 2 thread started (pid=2513, tid=4212) May 17 21:59:03 [vdr] [4213] TS buffer on device 2 thread started (pid=2513, tid=4213) May 17 21:59:03 [vdr] [2513] OSD size changed to 720x576 @ 1.06667 May 17 21:59:03 [vdr] [2513] connect from 127.0.0.1, port 34864 - accepted 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
Dont see anything obvious about why in transfer mode. This was the first occurance of transfer in the log at 21:59:06.
I guess I'll try to build a monitoring for this with metalog and logwatch to see how often it happens. Also trying to add print statements as suggested.
Cheers
On 21.05.2012 22:26, 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@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,
VDR has two Cards:
May 17 21:54:30 [kernel] DDBridge driver detected: Digital Devices Cine S2 V6 DVB adapter May 17 21:54:30 [kernel] HW 00010007 FW 00010003 May 17 21:54:30 [kernel] Port 0 (TAB 1): DUAL DVB-S2 May 17 21:54:30 [kernel] Port 1 (TAB 2): NO MODULE May 17 21:54:30 [kernel] Port 2 (TAB 3): NO MODULE May 17 21:54:30 [kernel] DVB: registering new adapter (DDBridge) May 17 21:54:30 [kernel] LNBx2x attached on addr=a May 17 21:54:30 [kernel] stv6110x_attach: Attaching STV6110x May 17 21:54:30 [kernel] attach tuner input 0 adr 60 May 17 21:54:30 [kernel] DVB: registering adapter 0 frontend 0 (STV090x Multistandard)... May 17 21:54:30 [kernel] DVB: registering new adapter (DDBridge) May 17 21:54:30 [kernel] LNBx2x attached on addr=8 May 17 21:54:30 [kernel] stv6110x_attach: Attaching STV6110x May 17 21:54:30 [kernel] attach tuner input 1 adr 63 May 17 21:54:30 [kernel] DVB: registering adapter 1 frontend 0 (STV090x Multistandard)... May 17 21:54:30 [kernel] Linux media interface: v0.10 May 17 21:54:30 [kernel] Linux video capture interface: v2.00 May 17 21:54:30 [kernel] WARNING: You are using an experimental version of the media stack. May 17 21:54:30 [kernel] _As the driver is backported to an older kernel, it doesn't offer May 17 21:54:30 [kernel] _enough quality for its usage in production. May 17 21:54:30 [kernel] _Use it with care. May 17 21:54:30 [kernel] Latest git patches (needed if you report a bug tolinux-media@vger.kernel.org): May 17 21:54:30 [kernel] _2f4cf2c3a971c4d5154def8ef9ce4811d702852d [media] dib9000: release a lock on error May 17 21:54:30 [kernel] _4c4364e022f8422e602edbb97a2d873dc0b6c769 [media] mxl111sf: fix a couple precedence bugs May 17 21:54:30 [kernel] _446b792c6bd87de4565ba200b75a708b4c575a06 [media] media: DocBook: Fix trivial typo in Sub-device Interface May 17 21:54:30 [kernel] saa7146: register extension 'av7110' May 17 21:54:30 [kernel] av7110 0000:07:01.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 May 17 21:54:30 [kernel] saa7146: found saa7146 @ mem f943a000 (revision 1, irq 16) (0x13c2,0x0000) May 17 21:54:30 [kernel] DVB: registering new adapter (Technotrend/Hauppauge WinTV DVB-S rev1.X or Fujitsu Siemens DVB-C) May 17 21:54:30 [kernel] adapter has MAC addr = 00:d0:5c:01:02:fd May 17 21:54:30 [kernel] dvb-ttpci: gpioirq unknown type=0 len=0 May 17 21:54:30 [kernel] dvb-ttpci: info @ card 2: firm f0240009, rtsl b0250018, vid 71010068, app 8000261d May 17 21:54:30 [kernel] dvb-ttpci: firmware @ card 2 supports CI link layer interface May 17 21:54:30 [kernel] dvb-ttpci: adac type set to 0 @ card 2 May 17 21:54:30 [kernel] saa7146_vv: saa7146 (0): registered device video0 [v4l2] May 17 21:54:30 [kernel] saa7146_vv: saa7146 (0): registered device vbi0 [v4l2] May 17 21:54:30 [kernel] ves1x93: Detected ves1893a rev2 May 17 21:54:30 [kernel] DVB: registering adapter 2 frontend 0 (VLSI VES1x93 DVB-S)...
0/0 = Cine S2 1/0 = Cine S2 2/0 = FF
May 17 21:54:35 [vdr] [2513] setting primary device to 2
In case I need to watch this VDR.
May 17 21:54:37 [vdr] [2513] switching to channel 2 May 17 21:54:37 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 2: ProvidesChannel 2 on device 1. Priority is 0, hasPriority is 1 May 17 21:54:37 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: Request for channel 2 on device 3. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: ProvidesChannel 2 on device 2. Priority is 0, hasPriority is 1 May 17 21:54:37 [vdr] [2513] LNB 3: Request for channel 2 on device 3. MaxBadPriority is -2 May 17 21:54:37 [vdr] [2513] LNB 3: Switching device 2 to channel 2 May 17 21:54:37 [vdr] [2513] LNB 3: Device check for channel 2 on device 2. OK May 17 21:54:37 [vdr] [2513] setting watchdog timer to 60 seconds May 17 21:54:37 [vdr] [2573] CAM 1: no module present May 17 21:54:37 [vdr] [2573] CAM 2: no module present May 17 21:54:37 [vdr] [2513] OSD size changed to 720x576 @ 1.06667 May 17 21:54:37 [vdr] [2560] video directory scanner thread ended (pid=2513, tid=2560)
May 17 21:54:37 [vdr] [2513] timer 2 (1 2159-2310 'Close') set to event Thu 17.05.2012 22:00-23:00 'New Tricks'
Times seem to be set OK. But Margin start = 1 and Margin stop = 2 on this VDR. No messages about stopping the recording around 23:02.
That's no surprise - the timer ends at *23:10*. Are you absolutely sure your "stop margin" is 2 and not 10?
ay 17 21:58:06 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:58:06 [vdr] [2513] switching device 1 to channel 1 May 17 21:58:06 [vdr] [2513] LNB 2: Switching device 1 to channel 1 May 17 21:58:06 [vdr] [2513] LNB 2: Device check for channel 1 on device
- OK
May 17 21:59:00 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 2: ProvidesChannel 1 on device 1. Priority is 99, hasPriority is 1 May 17 21:59:00 [vdr] [2513] LNB 2: Request for channel 1 on device 2. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 3: Request for channel 1 on device 3. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] LNB 3: ProvidesChannel 1 on device 2. Priority is 99, hasPriority is 1 May 17 21:59:00 [vdr] [2513] LNB 3: Request for channel 1 on device 3. MaxBadPriority is -2 May 17 21:59:00 [vdr] [2513] switching device 2 to channel 1 May 17 21:59:00 [vdr] [2513] LNB 3: Switching device 2 to channel 1 May 17 21:59:00 [vdr] [2513] LNB 3: Device check for channel 1 on device 2. OK May 17 21:59:00 [vdr] [2513] timer 2 (1 2159-2310 'Close') start May 17 21:59:00 [vdr] [2513] Title: 'New Tricks' Subtitle: 'Lost in Translation' May 17 21:59:00 [vdr] [2513] executing '/tmp/vdr/vdr_record before "/video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec"' May 17 21:59:00 [logger] BJD g2v_record.sh Called: 0 = /tmp/vdr/vdr_record May 17 21:59:00 [logger] 2012-05-17 21:59 /tmp/vdr/vdr_record before /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:00 [logger] /usr/sbin/mailtext: Started Start 2012-05-17 21.59 Lost in Translation. May 17 21:59:00 [logger] [g2v_rec_msg.sh] Close~Lost in Translation: Warte auf Verzeichnis - Last output repeated 3 times - May 17 21:59:02 [sSMTP] Sent mail forBrian_dorling@t-online.de (221 2.0.0 fwd19.t-online.de closing. / Verbindung wird getrennt.) u id=0 username=root outbytes=436 May 17 21:59:02 [logger] May 17 21:59:02 gen2vdr sendemail[3873]: Email was sent successfully! May 17 21:59:02 [logger] /usr/sbin/mailtext: Done May 17 21:59:02 [vdr] [2513] record /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:02 [vdr] [2513] creating directory /video/Close/Lost_in_Translation May 17 21:59:02 [vdr] [2513] creating directory /video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec May 17 21:59:02 [vdr] [2513] recording to '/video/Close/Lost_in_Translation/2012-05-17.21.59.1-0.rec/00001.ts' May 17 21:59:02 [vdr] [3992] recording thread started (pid=2513, tid=3992) May 17 21:59:02 [vdr] [3993] receiver on device 3 thread started (pid=2513, tid=3993) May 17 21:59:02 [vdr] [3995] TS buffer on device 3 thread started (pid=2513, tid=3995) May 17 21:59:02 [logger] [g2v_rec_msg.sh] Aufnahme: Close~Lost in Translation May 17 21:59:03 [vdr] [2513] switching to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:59:03 [vdr] [2513] LNB 2: ProvidesChannel 2 on device 1. Priority is 0, hasPriority is 1 May 17 21:59:03 [vdr] [2513] LNB 2: Request for channel 2 on device 2. MaxBadPriority is -2 May 17 21:59:03 [vdr] [2513] LNB 3: ProvidesChannel 2 on device 2. Priority is 0, hasPriority is 0 May 17 21:59:03 [vdr] [2513] LNB 3: Switching device 2 to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Switching device 1 to channel 2 May 17 21:59:03 [vdr] [2513] LNB 2: Device check for channel 2 on device
- OK
May 17 21:59:03 [vdr] [4212] receiver on device 2 thread started (pid=2513, tid=4212) May 17 21:59:03 [vdr] [4213] TS buffer on device 2 thread started (pid=2513, tid=4213) May 17 21:59:03 [vdr] [2513] OSD size changed to 720x576 @ 1.06667 May 17 21:59:03 [vdr] [2513] connect from 127.0.0.1, port 34864 - accepted 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
Dont see anything obvious about why in transfer mode. This was the first occurance of transfer in the log at 21:59:06.
I guess I'll try to build a monitoring for this with metalog and logwatch to see how often it happens. Also trying to add print statements as suggested.
And you also might want to switch to the latest developer version (1.7.27) and use "device bonding" instead of "lnb sharing" (just in case this makes a difference).
Klaus
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@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@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
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@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
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@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@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
On 08.06.2012 12:39, brian wrote:
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@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
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.
This is done once every main program loop, which is normally executed once per second. However, if the replay progress display is open it is executed more often. Maybe that's what's causing it?
Klaus
On Fri, May 18, 2012 at 12:49 AM, brian Brian_Dorling@t-online.de wrote:
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
Are you using softhddevice by chance? I also see these messages in my logs but only when using softhddevice. The video is frozen but as Klaus suggested, tuning a new channel fixes it. But, I don't have this problem when using vdr-xine so I believe the problem is in softhddevice and not my actual device. I haven't had any time to look into however. Anyone with any further info about this, please share!
Thanks
-
brian -
Klaus Schmidinger -
VDR User