Added debug output for checking the correct sequence of locking global lists

8 files changed, 191 insertions, 20 deletions

diff --git a/CONTRIBUTORS b/CONTRIBUTORS
index 140ae533..9f342077 100644
--- a/CONTRIBUTORS
+++ b/CONTRIBUTORS
@@ -3424,6 +3424,8 @@ Jasmin Jessich <jasmin@anw.at>
  debugging MTD support
  for fixing selecting delivery system names in case of undefined indexes
  for fixing detecting the inclusion of STL header files in tools.h
+ for help and suggestions when implementing debug output for checking the correct
+ sequence of locking global lists
 
 Martin Schirrmacher <schirrmie@gmail.com>
  for suggesting to provide a way for skin plugins to get informed about the currently
diff --git a/HISTORY b/HISTORY
index 7ce65868..adb33c05 100644
--- a/HISTORY
+++ b/HISTORY
@@ -9055,3 +9055,11 @@ Video Disk Recorder Revision History
   The newplugin script has also been modified accordingly.
 - Fixed detecting the inclusion of STL header files in tools.h (thanks to Jasmin
   Jessich).
+
+2017-05-28: Version 2.3.6
+
+- Added debug output for checking the correct sequence of locking global lists
+  (with help and suggestions from Jasmin Jessich). To activate this, define the
+  macro DEBUG_LOCKSEQ in thread.c. At the first occurrence of an invalid locking
+  sequence, the 20 most recent locks will be printed to stderr, followed by a
+  backtrace that led to the call in question.
diff --git a/channels.c b/channels.c
index 24fec5be..1b9aa86f 100644
--- a/channels.c
+++ b/channels.c
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: channels.c 4.3 2015/09/09 10:21:22 kls Exp $
+ * $Id: channels.c 4.4 2017/05/26 15:43:54 kls Exp $
  */
 
 #include "channels.h"
@@ -833,7 +833,7 @@ int cChannels::maxChannelNameLength = 0;
 int cChannels::maxShortChannelNameLength = 0;
 
 cChannels::cChannels(void)
-:cConfig<cChannel>("Channels")
+:cConfig<cChannel>("2 Channels")
 {
   modifiedByUser = 0;
 }
diff --git a/config.h b/config.h
index c67b990d..1b6e996e 100644
--- a/config.h
+++ b/config.h
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: config.h 4.9 2017/04/29 13:33:13 kls Exp $
+ * $Id: config.h 4.10 2017/05/28 12:42:49 kls Exp $
  */
 
 #ifndef __CONFIG_H
@@ -22,13 +22,13 @@
 
 // VDR's own version number:
 
-#define VDRVERSION  "2.3.5"
-#define VDRVERSNUM   20305  // Version * 10000 + Major * 100 + Minor
+#define VDRVERSION  "2.3.6"
+#define VDRVERSNUM   20306  // Version * 10000 + Major * 100 + Minor
 
 // The plugin API's version number:
 
-#define APIVERSION  "2.3.5"
-#define APIVERSNUM   20305  // Version * 10000 + Major * 100 + Minor
+#define APIVERSION  "2.3.6"
+#define APIVERSNUM   20306  // Version * 10000 + Major * 100 + Minor
 
 // When loading plugins, VDR searches them by their APIVERSION, which
 // may be smaller than VDRVERSION in case there have been no changes to
diff --git a/epg.c b/epg.c
index 7cbb0116..3955d702 100644
--- a/epg.c
+++ b/epg.c
@@ -7,7 +7,7 @@
  * Original version (as used in VDR before 1.3.0) written by
  * Robert Schneider <Robert.Schneider@web.de> and Rolf Hakenes <hakenes@hippomi.de>.
  *
- * $Id: epg.c 4.6 2017/05/09 12:16:36 kls Exp $
+ * $Id: epg.c 4.7 2017/05/28 11:30:32 kls Exp $
  */
 
 #include "epg.h"
@@ -1225,7 +1225,7 @@ char *cSchedules::epgDataFileName = NULL;
 time_t cSchedules::lastDump = time(NULL);
 
 cSchedules::cSchedules(void)
-:cList<cSchedule>("Schedules")
+:cList<cSchedule>("5 Schedules")
 {
 }
 
diff --git a/recording.c b/recording.c
index 9f96b73d..7b1d158b 100644
--- a/recording.c
+++ b/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 4.8 2017/04/03 13:34:30 kls Exp $
+ * $Id: recording.c 4.9 2017/05/27 15:46:57 kls Exp $
  */
 
 #include "recording.h"
@@ -1469,7 +1469,7 @@ cVideoDirectoryScannerThread *cRecordings::videoDirectoryScannerThread = NULL;
 time_t cRecordings::lastUpdate = 0;
 
 cRecordings::cRecordings(bool Deleted)
-:cList<cRecording>(Deleted ? "DelRecs" : "Recordings")
+:cList<cRecording>(Deleted ? "4 DelRecs" : "3 Recordings")
 {
 }
 
diff --git a/thread.c b/thread.c
index 2f57f815..32ce7c3f 100644
--- a/thread.c
+++ b/thread.c
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: thread.c 4.2 2016/12/08 10:18:32 kls Exp $
+ * $Id: thread.c 4.3 2017/05/28 12:41:03 kls Exp $
  */
 
 #include "thread.h"
@@ -24,6 +24,7 @@
 #define ABORT { dsyslog("ABORT!"); abort(); } // use debugger to trace back the problem
 
 //#define DEBUG_LOCKING // uncomment this line to activate debug output for locking
+//#define DEBUG_LOCKSEQ // uncomment this line to activate debug output for locking sequence
 
 #ifdef DEBUG_LOCKING
 #define dbglocking(a...) fprintf(stderr, a)
@@ -431,6 +432,163 @@ bool cThreadLock::Lock(cThread *Thread)
 
 // --- cStateLock ------------------------------------------------------------
 
+#ifdef DEBUG_LOCKSEQ
+#include <cxxabi.h>
+#include <execinfo.h>
+static cVector<tThreadId> StateLockThreadIds;
+static cVector<int> StateLockFlags;
+static cMutex StateLockMutex;
+#define SLL_SIZE     20 // the number of log entries
+#define SLL_LENGTH  256 // the maximum length of log entries
+#define SLL_DELIM   '#' // delimiter for caller info
+static char StateLockLog[SLL_SIZE][SLL_LENGTH] = { 0 };
+static int StateLockLogIndex = 0;
+static bool DumpStateLocks = true;
+#define BT_BUF_SIZE 100
+
+static cString Demangle(char *s, char *Prefix = NULL)
+{
+  char *Module = s;
+  char *Function = NULL;
+  //char *Offset = NULL;
+  char *Address = NULL;
+  // separate the string:
+  for (char *q = Module; *q; q++) {
+      if (*q == '(') {
+         *q = 0;
+         Function = q + 1;
+         }
+      else if (*q == '+') {
+         *q = 0;
+         //Offset = q + 1;
+         }
+      else if (*q == ')')
+         *q = 0;
+      else if (*q == '[')
+         Address = q + 1;
+      else if (*q == ']') {
+         *q = 0;
+         break;
+         }
+      }
+  // demangle the function name:
+  int status;
+  char *r = abi::__cxa_demangle(Function, NULL, 0, &status);
+  if (r)
+     Function = r;
+  cString d = cString::sprintf("%s %s %s", Prefix ? Prefix : "", Module, Function);
+  // determine the file name and line number:
+  cString cmd = cString::sprintf("addr2line --exe=%s --functions --demangle --basename %s", Module, Address);
+  cPipe p;
+  if (p.Open(cmd, "r")) {
+     int n = 0;
+     cReadLine rl;
+     while (char *l = rl.Read(p)) {
+           if (n == 0) {
+              if (!isempty(Function) && strcmp(l, Function))
+                 d = cString::sprintf("%s calling %s", *d, l);
+              }
+           else
+              d = cString::sprintf("%s at %s", *d, l);
+           n++;
+           }
+     p.Close();
+     }
+  free(r);
+  return d;
+}
+
+static void BackTrace(void)
+{
+  void *b[BT_BUF_SIZE];
+  int n = backtrace(b, BT_BUF_SIZE);
+  if (char **s = backtrace_symbols(b, n)) {
+     for (int i = 5; i < n; i++)
+         fprintf(stderr, "%s\n", *Demangle(s[i]));
+     free(s);
+     }
+}
+
+static void BackTraceCaller(int Level, char *t, int l)
+{
+  void *b[BT_BUF_SIZE];
+  int n = backtrace(b, BT_BUF_SIZE);
+  if (char **s = backtrace_symbols(b, n)) {
+     strn0cpy(t, s[Level], l);
+     free(s);
+     }
+}
+
+static void DumpStateLockLog(tThreadId ThreadId, const char *Name)
+{
+  if (!DumpStateLocks)
+     return;
+  DumpStateLocks = false;
+  for (int i = 0; i < SLL_SIZE; i++) {
+      char *s = StateLockLog[StateLockLogIndex];
+      if (*s) {
+         if (char *Delim = strchr(s, SLL_DELIM)) {
+            *Delim = 0;
+            fprintf(stderr, "%s\n", *Demangle(Delim + 1, s));
+            }
+         }
+      if (++StateLockLogIndex >= SLL_SIZE)
+         StateLockLogIndex = 0;
+      }
+  fprintf(stderr, "%5d invalid lock sequence: %-12s\n", ThreadId, Name);
+  fprintf(stderr, "full backtrace:\n");
+  BackTrace();
+}
+
+static void CheckStateLockLevel(const char *Name, bool Lock, bool Write = false)
+{
+  if (Name) {
+     int n = *Name - '0';
+     if (1 <= n && n <= 9) {
+        int b = 1 << (n - 1);
+        cMutexLock MutexLock(&StateLockMutex);
+        tThreadId ThreadId = cThread::ThreadId();
+        int Index = StateLockThreadIds.IndexOf(ThreadId);
+        if (Index < 0) {
+           if (Lock) {
+              Index = StateLockThreadIds.Size();
+              StateLockThreadIds.Append(ThreadId);
+              StateLockFlags.Append(0);
+              }
+           else
+              return;
+           }
+        char *p = StateLockLog[StateLockLogIndex];
+        char *q = p;
+        q += sprintf(q, "%5d", ThreadId);
+        for (int i = 0; i <= 9; i++) {
+            char c = '-';
+            if (StateLockFlags[Index] & (1 << i))
+               c = '*';
+            if (i == n - 1)
+               c = Lock ? Write ? 'W' : 'R' : '-';
+            q += sprintf(q, "  %c", c);
+            }
+        q += sprintf(q, " %c%c", Lock ? 'L' : 'U', SLL_DELIM);
+        BackTraceCaller(Lock ? 5 : 3, q, SLL_LENGTH - (q - p));
+        if (++StateLockLogIndex >= SLL_SIZE)
+           StateLockLogIndex = 0;
+        if (Lock) {
+           if ((StateLockFlags[Index] & ~b) < b)
+              StateLockFlags[Index] |= b;
+           else if ((StateLockFlags[Index] & b) == 0)
+              DumpStateLockLog(ThreadId, Name);
+           }
+        else
+           StateLockFlags[Index] &= ~b;
+        }
+     }
+}
+#define dbglockseq(n, l, w) CheckStateLockLevel(n, l, w)
+#else
+#define dbglockseq(n, l, w)
+#endif // DEBUG_LOCKSEQ
+
 cStateLock::cStateLock(const char *Name)
 :rwLock(true)
 {
@@ -442,7 +600,7 @@ cStateLock::cStateLock(const char *Name)
 
 bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
 {
-  dbglocking("%5d %-10s %10p   lock state = %d/%d write = %d timeout = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, Write, TimeoutMs);
+  dbglocking("%5d %-12s %10p   lock state = %d/%d write = %d timeout = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, Write, TimeoutMs);
   StateKey.timedOut = false;
   if (StateKey.stateLock) {
      esyslog("ERROR: StateKey already in use in call to cStateLock::Lock() (tid=%d, lock=%s)", StateKey.stateLock->threadId, name);
@@ -450,25 +608,27 @@ bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
      return false;
      }
   if (rwLock.Lock(Write, TimeoutMs)) {
+     dbglockseq(name, true, Write);
      StateKey.stateLock = this;
      if (Write) {
-        dbglocking("%5d %-10s %10p   locked write\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   locked write\n", cThread::ThreadId(), name, &StateKey);
         threadId = cThread::ThreadId();
         StateKey.write = true;
         return true;
         }
      else if (state != StateKey.state) {
-        dbglocking("%5d %-10s %10p   locked read\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   locked read\n", cThread::ThreadId(), name, &StateKey);
         return true;
         }
      else {
-        dbglocking("%5d %-10s %10p   state unchanged\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   state unchanged\n", cThread::ThreadId(), name, &StateKey);
         StateKey.stateLock = NULL;
+        dbglockseq(name, false, false);
         rwLock.Unlock();
         }
      }
   else if (TimeoutMs) {
-     dbglocking("%5d %-10s %10p   timeout\n", cThread::ThreadId(), name, &StateKey);
+     dbglocking("%5d %-12s %10p   timeout\n", cThread::ThreadId(), name, &StateKey);
      StateKey.timedOut = true;
      }
   return false;
@@ -476,7 +636,7 @@ bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
 
 void cStateLock::Unlock(cStateKey &StateKey, bool IncState)
 {
-  dbglocking("%5d %-10s %10p unlock state = %d/%d inc = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, IncState);
+  dbglocking("%5d %-12s %10p unlock state = %d/%d inc = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, IncState);
   if (StateKey.stateLock != this) {
      esyslog("ERROR: cStateLock::Unlock() called with an unused key (tid=%d, lock=%s)", threadId, name);
      ABORT;
@@ -495,6 +655,7 @@ void cStateLock::Unlock(cStateKey &StateKey, bool IncState)
      threadId = 0;
      explicitModify = false;
      }
+  dbglockseq(name, false, false);
   rwLock.Unlock();
 }
 
diff --git a/timers.c b/timers.c
index 4cf8fb7f..95cb723b 100644
--- a/timers.c
+++ b/timers.c
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: timers.c 4.9 2017/04/20 09:15:06 kls Exp $
+ * $Id: timers.c 4.10 2017/05/26 15:43:38 kls Exp $
  */
 
 #include "timers.h"
@@ -714,7 +714,7 @@ cTimers cTimers::timers;
 int cTimers::lastTimerId = 0;
 
 cTimers::cTimers(void)
-:cConfig<cTimer>("Timers")
+:cConfig<cTimer>("1 Timers")
 {
   lastDeleteExpired = 0;
 }