Recordings are now checked for errors

HISTORY

@@ -9663,10 +9663,19 @@ Video Disk Recorder Revision History
 - EXPIRELATENCY now only applies to VPS timers.
 - Deleting expired timers is now triggered immediately after the timers are modified.
 
-2021-05-11:
+2021-05-19:
 
 - Now using a separate fixed value for internal EPG linger time. This fixes problems with
   spawned timers jumping to the next event in case Setup.EPGLinger is very small. (reported
   by Jürgen Schneider).
 - Fixed a possible crash in the Schedule menu, in case Setup.EPGLinger is 0.
 - Fixed cTsPayload::AtPayloadStart() to ignore TS packets from other PIDs.
+- Recordings are now checked for errors:
+  + On TS level, the continuity counter, transport error indicator and scramble flags are
+    checked.
+  + On frame level it is checked whether there are no gaps in the PTS.
+  + The number of errors during a recording is stored in the recording's 'info' file, with
+    the new tag 'O'.
+  + Spawned timers that shall avoid recording reruns only store the recording's name in
+    the donerecs,data file if there were no errors during recording, and if the timer has
+    actually finished.

menu.c

@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: menu.c 5.4 2021/04/17 09:44:01 kls Exp $
+ * $Id: menu.c 5.5 2021/05/19 11:22:20 kls Exp $
  */
 
 #include "menu.h"
@@ -5401,6 +5401,15 @@ bool cRecordControl::GetEvent(void)
 void cRecordControl::Stop(bool ExecuteUserCommand)
 {
   if (timer) {
+     if (recorder) {
+        int Errors = recorder->Errors();
+        bool Finished = timer->HasFlags(tfActive) && !timer->Matches();
+        isyslog("timer %s %s with %d error%s", *timer->ToDescr(), Finished ? "finished" : "stopped", Errors, Errors != 1 ? "s" : "");
+        if (timer->HasFlags(tfAvoid) && Errors == 0 && Finished) {
+           const char *p = strgetlast(timer->File(), FOLDERDELIMCHAR);
+           DoneRecordingsPattern.Append(p);
+           }
+        }
      DELETENULL(recorder);
      timer->SetRecording(false);
      timer = NULL;
@@ -5414,13 +5423,8 @@ void cRecordControl::Stop(bool ExecuteUserCommand)
 bool cRecordControl::Process(time_t t)
 {
   if (!recorder || !recorder->IsAttached() || !timer || !timer->Matches(t)) {
-     if (timer) {
+     if (timer)
         timer->SetPending(false);
-        if (timer->HasFlags(tfAvoid)) {
-           const char *p = strgetlast(timer->File(), FOLDERDELIMCHAR);
-           DoneRecordingsPattern.Append(p);
-           }
-        }
      return false;
      }
   return true;

recorder.c

@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: recorder.c 4.4 2015/09/12 14:56:15 kls Exp $
+ * $Id: recorder.c 5.1 2021/05/19 11:22:20 kls Exp $
  */
 
 #include "recorder.h"
@@ -19,13 +19,160 @@
 #define MINFREEDISKSPACE    (512) // MB
 #define DISKCHECKINTERVAL   100 // seconds
 
+static bool DebugChecks = false;
+
+// cTsChecker and cFrameChecker are used to detect errors in the recorded data stream.
+// While cTsChecker checks the continuity counter of the incoming TS packets, cFrameChecker
+// works on entire frames, checking their PTS (Presentation Time Stamps) to see whether
+// all expected frames arrive. The resulting number of errors is not a precise value.
+// If it is zero, the recording can be safely considered error free. The higher the value,
+// the more damaged the recording is.
+
+// --- cTsChecker ------------------------------------------------------------
+
+#define TS_CC_UNKNOWN    0xFF
+
+class cTsChecker {
+private:
+  uchar counter[MAXPID];
+  int errors;
+  void Report(int Pid, const char *Message);
+public:
+  cTsChecker(void);
+  void CheckTs(const uchar *Data, int Length);
+  int Errors(void) { return errors; }
+  };
+
+cTsChecker::cTsChecker(void)
+{
+  memset(counter, TS_CC_UNKNOWN, sizeof(counter));
+  errors = 0;
+}
+
+void cTsChecker::Report(int Pid, const char *Message)
+{
+  errors++;
+  if (DebugChecks)
+     fprintf(stderr, "%s: TS error #%d on PID %d (%s)\n", *TimeToString(time(NULL)), errors, Pid, Message);
+}
+
+void cTsChecker::CheckTs(const uchar *Data, int Length)
+{
+  int Pid = TsPid(Data);
+  uchar Cc = TsContinuityCounter(Data);
+  if (TsHasPayload(Data)) {
+     if (TsError(Data))
+        Report(Pid, "tei");
+     else if (TsIsScrambled(Data))
+        Report(Pid, "scrambled");
+     else {
+        uchar OldCc = counter[Pid];
+        if (OldCc != TS_CC_UNKNOWN) {
+           uchar NewCc = (OldCc + 1) & TS_CONT_CNT_MASK;
+           if (Cc != NewCc)
+              Report(Pid, "continuity");
+           }
+        }
+     }
+  counter[Pid] = Cc;
+}
+
+// --- cFrameChecker ---------------------------------------------------------
+
+#define MAX_BACK_REFS  32
+
+class cFrameChecker {
+private:
+  int frameDelta;
+  int64_t lastPts;
+  uint32_t backRefs;
+  int lastFwdRef;
+  int errors;
+  void Report(const char *Message, int NumErrors = 1);
+public:
+  cFrameChecker(void);
+  void SetFrameDelta(int FrameDelta) { frameDelta = FrameDelta; }
+  void CheckFrame(const uchar *Data, int Length);
+  void ReportBroken(void);
+  int Errors(void) { return errors; }
+  };
+
+cFrameChecker::cFrameChecker(void)
+{
+  frameDelta = PTSTICKS / DEFAULTFRAMESPERSECOND;
+  lastPts = -1;
+  backRefs = 0;
+  lastFwdRef = 0;
+  errors = 0;
+}
+
+void cFrameChecker::Report(const char *Message, int NumErrors)
+{
+  errors += NumErrors;
+  if (DebugChecks)
+     fprintf(stderr, "%s: frame error #%d (%s)\n", *TimeToString(time(NULL)), errors, Message);
+}
+
+void cFrameChecker::CheckFrame(const uchar *Data, int Length)
+{
+  int64_t Pts = TsGetPts(Data, Length);
+  if (Pts >= 0) {
+     if (lastPts >= 0) {
+        int Diff = int(round((PtsDiff(lastPts, Pts) / double(frameDelta))));
+        if (Diff > 0) {
+           if (Diff <= MAX_BACK_REFS) {
+              if (lastFwdRef > 1) {
+                 if (backRefs != uint32_t((1 << (lastFwdRef - 1)) - 1))
+                    Report("missing backref");
+                 }
+              }
+           else
+              Report("missed", Diff);
+           backRefs = 0;
+           lastFwdRef = Diff;
+           lastPts = Pts;
+           }
+        else if (Diff < 0) {
+           Diff = -Diff;
+           if (Diff <= MAX_BACK_REFS) {
+              int b = 1 << (Diff - 1);
+              if ((backRefs & b) != 0)
+                 Report("duplicate backref");
+              backRefs |= b;
+              }
+           else
+              Report("rev diff too big");
+           }
+        else
+           Report("zero diff");
+        }
+     else
+        lastPts = Pts;
+     }
+  else
+     Report("no PTS");
+}
+
+void cFrameChecker::ReportBroken(void)
+{
+  int MissedFrames = MAXBROKENTIMEOUT / 1000 * PTSTICKS / frameDelta;
+  Report("missed", MissedFrames);
+}
+
 // --- cRecorder -------------------------------------------------------------
 
 cRecorder::cRecorder(const char *FileName, const cChannel *Channel, int Priority)
 :cReceiver(Channel, Priority)
 ,cThread("recording")
 {
+  tsChecker = new cTsChecker;
+  frameChecker = new cFrameChecker;
   recordingName = strdup(FileName);
+  recordingInfo = new cRecordingInfo(recordingName);
+  recordingInfo->Read();
+  oldErrors = recordingInfo->Errors(); // in case this is a re-started recording
+  errors = oldErrors;
+  firstIframeSeen = false;
 
   // Make sure the disk is up and running:
 
@@ -49,6 +196,7 @@ cRecorder::cRecorder(const char *FileName, const cChannel *Channel, int Priority
   index = NULL;
   fileSize = 0;
   lastDiskSpaceCheck = time(NULL);
+  lastErrorLog = 0;
   fileName = new cFileName(FileName, true);
   int PatVersion, PmtVersion;
   if (fileName->GetLastPatPmtVersions(PatVersion, PmtVersion))
@@ -71,9 +219,31 @@ cRecorder::~cRecorder()
   delete fileName;
   delete frameDetector;
   delete ringBuffer;
+  delete frameChecker;
+  delete tsChecker;
   free(recordingName);
 }
 
+#define ERROR_LOG_DELTA 1 // seconds between logging errors
+
+void cRecorder::HandleErrors(bool Force)
+{
+  // We don't log every single error separately, to avoid spamming the log file:
+  if (Force || time(NULL) - lastErrorLog >= ERROR_LOG_DELTA) {
+     errors = tsChecker->Errors() + frameChecker->Errors();
+     if (errors > lastErrors) {
+        int d = errors - lastErrors;
+        if (DebugChecks)
+           fprintf(stderr, "%s: %s: %d error%s\n", *TimeToString(time(NULL)), recordingName, d, d > 1 ? "s" : "");
+        esyslog("%s: %d error%s", recordingName, d, d > 1 ? "s" : "");
+        recordingInfo->SetErrors(oldErrors + errors);
+        recordingInfo->Write();
+        }
+     lastErrors = errors;
+     lastErrorLog = time(NULL);
+     }
+}
+
 bool cRecorder::RunningLowOnDiskSpace(void)
 {
   if (time(NULL) > lastDiskSpaceCheck + DISKCHECKINTERVAL) {
@@ -134,6 +304,8 @@ void cRecorder::Receive(const uchar *Data, int Length)
      int p = ringBuffer->Put(Data, Length);
      if (p != Length && Running())
         ringBuffer->ReportOverflow(Length - p);
+     else if (firstIframeSeen) // we ignore any garbage before the first I-frame
+        tsChecker->CheckTs(Data, Length);
      }
 }
 
@@ -141,7 +313,6 @@ void cRecorder::Action(void)
 {
   cTimeMs t(MAXBROKENTIMEOUT);
   bool InfoWritten = false;
-  bool FirstIframeSeen = false;
   while (Running()) {
         int r;
         uchar *b = ringBuffer->Get(r);
@@ -152,24 +323,26 @@ void cRecorder::Action(void)
                  break;
               if (frameDetector->Synced()) {
                  if (!InfoWritten) {
-                    cRecordingInfo RecordingInfo(recordingName);
+                    if (frameDetector->FramesPerSecond() > 0 && DoubleEqual(recordingInfo->FramesPerSecond(), DEFAULTFRAMESPERSECOND) && !DoubleEqual(recordingInfo->FramesPerSecond(), frameDetector->FramesPerSecond())) {
-                    if (RecordingInfo.Read()) {
+                       recordingInfo->SetFramesPerSecond(frameDetector->FramesPerSecond());
-                       if (frameDetector->FramesPerSecond() > 0 && DoubleEqual(RecordingInfo.FramesPerSecond(), DEFAULTFRAMESPERSECOND) && !DoubleEqual(RecordingInfo.FramesPerSecond(), frameDetector->FramesPerSecond())) {
+                       recordingInfo->Write();
-                          RecordingInfo.SetFramesPerSecond(frameDetector->FramesPerSecond());
+                       LOCK_RECORDINGS_WRITE;
-                          RecordingInfo.Write();
+                       Recordings->UpdateByName(recordingName);
-                          LOCK_RECORDINGS_WRITE;
-                          Recordings->UpdateByName(recordingName);
-                          }
                        }
                     InfoWritten = true;
                     cRecordingUserCommand::InvokeCommand(RUC_STARTRECORDING, recordingName);
+                    frameChecker->SetFrameDelta(PTSTICKS / frameDetector->FramesPerSecond());
                     }
-                 if (FirstIframeSeen || frameDetector->IndependentFrame()) {
+                 if (firstIframeSeen || frameDetector->IndependentFrame()) {
-                    FirstIframeSeen = true; // start recording with the first I-frame
+                    firstIframeSeen = true; // start recording with the first I-frame
                     if (!NextFile())
                        break;
-                    if (index && frameDetector->NewFrame())
+                    if (frameDetector->NewFrame()) {
-                       index->Write(frameDetector->IndependentFrame(), fileName->Number(), fileSize);
+                       if (index)
+                          index->Write(frameDetector->IndependentFrame(), fileName->Number(), fileSize);
+                       if (frameChecker)
+                          frameChecker->CheckFrame(b, Count);
+                       }
                     if (frameDetector->IndependentFrame()) {
                        recordFile->Write(patPmtGenerator.GetPat(), TS_SIZE);
                        fileSize += TS_SIZE;
@@ -184,6 +357,7 @@ void cRecorder::Action(void)
                        LOG_ERROR_STR(fileName->Name());
                        break;
                        }
+                    HandleErrors();
                     fileSize += Count;
                     }
                  }
@@ -191,9 +365,12 @@ void cRecorder::Action(void)
               }
            }
         if (t.TimedOut()) {
+           frameChecker->ReportBroken();
+           HandleErrors(true);
            esyslog("ERROR: video data stream broken");
            ShutdownHandler.RequestEmergencyExit();
            t.Set(MAXBROKENTIMEOUT);
            }
         }
+  HandleErrors(true);
 }

recorder.h

@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: recorder.h 4.1 2015/09/05 11:46:23 kls Exp $
+ * $Id: recorder.h 5.1 2021/05/19 11:22:20 kls Exp $
  */
 
 #ifndef __RECORDER_H
@@ -16,19 +16,31 @@
 #include "ringbuffer.h"
 #include "thread.h"
 
+class cTsChecker;
+class cFrameChecker;
+
 class cRecorder : public cReceiver, cThread {
 private:
+  cTsChecker *tsChecker;
+  cFrameChecker *frameChecker;
   cRingBufferLinear *ringBuffer;
   cFrameDetector *frameDetector;
   cPatPmtGenerator patPmtGenerator;
   cFileName *fileName;
+  cRecordingInfo *recordingInfo;
   cIndexFile *index;
   cUnbufferedFile *recordFile;
   char *recordingName;
+  bool firstIframeSeen;
   off_t fileSize;
   time_t lastDiskSpaceCheck;
+  time_t lastErrorLog;
+  int oldErrors;
+  int errors;
+  int lastErrors;
   bool RunningLowOnDiskSpace(void);
   bool NextFile(void);
+  void HandleErrors(bool Force = false);
 protected:
   virtual void Activate(bool On);
        ///< If you override Activate() you need to call Detach() (which is a
@@ -42,6 +54,8 @@ public:
        ///< Creates a new recorder for the given Channel and
        ///< the given Priority that will record into the file FileName.
   virtual ~cRecorder();
+  int Errors(void) { return oldErrors + errors; };
+       ///< Returns the number of errors that were detected during recording.
   };
 
 #endif //__RECORDER_H

recording.c

@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: recording.c 5.6 2021/03/17 10:55:43 kls Exp $
+ * $Id: recording.c 5.7 2021/05/19 11:22:20 kls Exp $
  */
 
 #include "recording.h"
@@ -359,6 +359,7 @@ cRecordingInfo::cRecordingInfo(const cChannel *Channel, const cEvent *Event)
   priority = MAXPRIORITY;
   lifetime = MAXLIFETIME;
   fileName = NULL;
+  errors = 0;
   if (Channel) {
      // Since the EPG data's component records can carry only a single
      // language code, let's see whether the channel's PID data has
@@ -414,6 +415,7 @@ cRecordingInfo::cRecordingInfo(const char *FileName)
   ownEvent = new cEvent(0);
   event = ownEvent;
   aux = NULL;
+  errors = 0;
   framesPerSecond = DEFAULTFRAMESPERSECOND;
   priority = MAXPRIORITY;
   lifetime = MAXLIFETIME;
@@ -456,6 +458,11 @@ void cRecordingInfo::SetFileName(const char *FileName)
   fileName = strdup(cString::sprintf("%s%s", FileName, IsPesRecording ? INFOFILESUFFIX ".vdr" : INFOFILESUFFIX));
 }
 
+void cRecordingInfo::SetErrors(int Errors)
+{
+  errors = Errors;
+}
+
 bool cRecordingInfo::Read(FILE *f)
 {
   if (ownEvent) {
@@ -499,6 +506,8 @@ bool cRecordingInfo::Read(FILE *f)
                        break;
              case 'P': priority = atoi(t);
                        break;
+             case 'O': errors = atoi(t);
+                       break;
              case '@': free(aux);
                        aux = strdup(t);
                        break;
@@ -523,6 +532,7 @@ bool cRecordingInfo::Write(FILE *f, const char *Prefix) const
   fprintf(f, "%sF %s\n", Prefix, *dtoa(framesPerSecond, "%.10g"));
   fprintf(f, "%sP %d\n", Prefix, priority);
   fprintf(f, "%sL %d\n", Prefix, lifetime);
+  fprintf(f, "%sO %d\n", Prefix, errors);
   if (aux)
      fprintf(f, "%s@ %s\n", Prefix, aux);
   return true;
@@ -1188,6 +1198,16 @@ void cRecording::ReadInfo(void)
 bool cRecording::WriteInfo(const char *OtherFileName)
 {
   cString InfoFileName = cString::sprintf("%s%s", OtherFileName ? OtherFileName : FileName(), isPesRecording ? INFOFILESUFFIX ".vdr" : INFOFILESUFFIX);
+  if (!OtherFileName) {
+     // Let's keep the error counter if this is a re-started recording:
+     cRecordingInfo ExistingInfo(FileName());
+     if (ExistingInfo.Read())
+        info->SetErrors(ExistingInfo.Errors());
+     }
+  else {
+     // This is an edited recording, so let's clear the error counter:
+     info->SetErrors(0);
+     }
   cSafeFile f(InfoFileName);
   if (f.Open()) {
      info->Write(f);

recording.h

@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: recording.h 5.3 2021/01/19 20:38:28 kls Exp $
+ * $Id: recording.h 5.4 2021/05/19 11:22:20 kls Exp $
  */
 
 #ifndef __RECORDING_H
@@ -72,6 +72,7 @@ private:
   int priority;
   int lifetime;
   char *fileName;
+  int errors;
   cRecordingInfo(const cChannel *Channel = NULL, const cEvent *Event = NULL);
   bool Read(FILE *f);
 public:
@@ -88,6 +89,8 @@ public:
   double FramesPerSecond(void) const { return framesPerSecond; }
   void SetFramesPerSecond(double FramesPerSecond);
   void SetFileName(const char *FileName);
+  int Errors(void) { return errors; }
+  void SetErrors(int Errors);
   bool Write(FILE *f, const char *Prefix = "") const;
   bool Read(void);
   bool Write(void) const;

vdr.5

@@ -8,7 +8,7 @@
 .\" License as specified in the file COPYING that comes with the
 .\" vdr distribution.
 .\"
-.\" $Id: vdr.5 5.1 2020/12/26 15:49:01 kls Exp $
+.\" $Id: vdr.5 5.2 2021/05/19 11:22:20 kls Exp $
 .\"
 .TH vdr 5 "15 Apr 2018" "2.4" "Video Disk Recorder Files"
 .SH NAME
@@ -817,8 +817,13 @@ l l.
 \fBF\fR|<frame rate>
 \fBL\fR|<lifetime>
 \fBP\fR|<priority>
+\fBO\fR|<errors>
 \fB@\fR|<auxiliary data>
 .TE
+
+The 'O' tag contains the number of errors that occurred during recording.
+If it is zero, the recording can be safely considered error free. The higher the value,
+the more damaged the recording is.
 .SS RESUME
 The file \fIresume\fR (if present in a recording directory) contains
 the position within the recording where the last replay session left off.