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