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 [2496] timer 1 (1
2159-2310 'Silent Witness') start
Apr 30 21:59:00 [2496] Title: 'Silent
Witness' Subtitle: 'Fear - Part Two'
Apr 30 21:59:00 [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@xxxxxxxxxxx (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 [2496] record
/video/Silent_Witness/2012-04-30.21.59.1-0.rec
Apr 30 21:59:01 [2496] creating directory
/video/Silent_Witness/2012-04-30.21.59.1-0.rec
Apr 30 21:59:02 [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 [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 [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 [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 [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 [3935] recording to
'/video/Silent_Witness/2012-04-30.21.59.1-0.rec/00003.ts'
May 01 00:24:40 [2779] TVTV: Packed
String: DKVxHLuoiXDxsDu98Eavvg==
....
May 01 01:23:04 [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 [2496] timer 1 (1
2159-2310 'Silent Witness') stop
May 01 06:37:39 [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 [3939] TS buffer on device
3 thread ended (pid=2496, tid=3939)
May 01 06:37:39 [3936] buffer stats: 95316
(4%) used
May 01 06:37:39 [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 [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
[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 [2513] SVDRP message: 'Aufnahme:
Close~Lost in Translation'
May 17 21:59:04 [2513] info: Aufnahme: Close~Lost
in Translation
May 17 21:59:04 [2513] closing SVDRP connection
May 17 21:59:06 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated twice -
May 17 21:59:08 [4213] buffer usage: 70%
(tid=4212)
May 17 21:59:08 [4212] ERROR: TS packet not
accepted in Transfer Mode
May 17 21:59:08 [4213] buffer usage: 80%
(tid=4212)
May 17 21:59:08 [4213] buffer usage: 90%
(tid=4212)
May 17 21:59:09 [4213] buffer usage: 100%
(tid=4212)
May 17 21:59:09 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 4 times -
May 17 21:59:13 [4218] video directory scanner
thread started (pid=2513, tid=4218)
May 17 21:59:13 [4219] video directory scanner
thread started (pid=2513, tid=4219)
May 17 21:59:13 [4219] video directory scanner
thread ended (pid=2513, tid=4219)
May 17 21:59:13 [4218] video directory scanner
thread ended (pid=2513, tid=4218)
Log is full with the following messages:
May 17 21:59:14 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated twice -
May 17 21:59:15 [4213] ERROR: driver buffer
overflow on device 2
May 17 21:59:16 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 8 times -
May 17 21:59:24 [4213] ERROR: driver buffer
overflow on device 2
May 17 21:59:25 [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 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:38 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 3 times -
May 17 23:19:41 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:42 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 3 times -
May 17 23:19:45 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:46 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 2 times -
May 17 23:19:48 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:49 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 3 times -
May 17 23:19:52 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:53 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 5 times -
May 17 23:19:58 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:19:59 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 5 times -
May 17 23:20:04 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:20:05 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 4 times -
May 17 23:20:09 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:20:11 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 4 times -
May 17 23:20:15 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:20:16 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 4 times -
May 17 23:20:20 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:20:21 [4212] ERROR: TS packet not
accepted in Transfer Mode
- Last output repeated 3 times -
May 17 23:20:24 [4213] ERROR: driver buffer
overflow on device 2
May 17 23:20:25 [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@xxxxxxxxxxx
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 [8428] Within 5 MInutes of end. timer data:
1339149540 1339151740 0 1339151760
- Last output repeated 13 times -
Jun 8 12:35:41 [8428] Within 5 MInutes of end. timer data:
1339149540 1339151741 0 1339151760
- Last output repeated twice -
Jun 8 12:35:41 [8428] closing SVDRP connection
Jun 8 12:35:41 [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
|
