Added backtrace functions for debugging

1 files changed, 168 insertions, 78 deletions

diff --git a/thread.c b/thread.c
index 32ce7c3f..345f2af4 100644
--- a/thread.c
+++ b/thread.c
@@ -4,27 +4,31 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: thread.c 4.3 2017/05/28 12:41:03 kls Exp $
+ * $Id: thread.c 4.4 2017/06/03 12:43:22 kls Exp $
  */
 
 #include "thread.h"
+#include <cxxabi.h>
+#include <dlfcn.h>
 #include <errno.h>
+#include <execinfo.h>
 #include <linux/unistd.h>
 #include <malloc.h>
 #include <stdarg.h>
 #include <stdlib.h>
+#include <sys/prctl.h>
 #include <sys/resource.h>
 #include <sys/syscall.h>
 #include <sys/time.h>
 #include <sys/wait.h>
-#include <sys/prctl.h>
 #include <unistd.h>
 #include "tools.h"
 
-#define ABORT { dsyslog("ABORT!"); abort(); } // use debugger to trace back the problem
+#define ABORT { dsyslog("ABORT!"); cBackTrace::BackTrace(); abort(); }
 
-//#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
+//#define DEBUG_LOCKING  // uncomment this line to activate debug output for locking
+#define DEBUG_LOCKSEQ  // uncomment this line to activate debug output for invalid locking sequence
+//#define DEBUG_LOCKCALL // uncomment this line to activate caller information with DEBUG_LOCKSEQ (WARNING: expensive operation, use only when actually debugging the locking sequence!)
 
 #ifdef DEBUG_LOCKING
 #define dbglocking(a...) fprintf(stderr, a)
@@ -430,27 +434,15 @@ bool cThreadLock::Lock(cThread *Thread)
   return false;
 }
 
-// --- cStateLock ------------------------------------------------------------
+// --- cBackTrace ------------------------------------------------------------
 
-#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)
+cString cBackTrace::Demangle(char *s)
 {
   char *Module = s;
   char *Function = NULL;
-  //char *Offset = NULL;
+  char *Offset = NULL;
   char *Address = NULL;
   // separate the string:
   for (char *q = Module; *q; q++) {
@@ -460,7 +452,7 @@ static cString Demangle(char *s, char *Prefix = NULL)
          }
       else if (*q == '+') {
          *q = 0;
-         //Offset = q + 1;
+         Offset = q + 1;
          }
       else if (*q == ')')
          *q = 0;
@@ -472,20 +464,46 @@ static cString Demangle(char *s, char *Prefix = NULL)
          }
       }
   // 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);
+  char *DemangledFunction = NULL;
+  if (Function) {
+     int status;
+     DemangledFunction = abi::__cxa_demangle(Function, NULL, 0, &status);
+     if (DemangledFunction)
+        Function = DemangledFunction;
+     if (!*Function)
+        Function = NULL;
+     }
+  cString d = cString::sprintf("%s%s%s", Module, Function ? " " : "", Function ? Function : "");
+  // convert string address to numbers:
+  unsigned long long addr = Address ? strtoull(Address, NULL, 0) : 0;
+  unsigned long long offs = Offset ? strtoull(Offset, NULL, 0) : 0;
+  // for shared libraries we need get the offset inside the library:
+  if (Function) {
+     // check whether the module name ends with ".so*":
+     char *e = Module;
+     char *p = NULL;
+     while (e = strstr(e, ".so"))
+           p = e++;
+     if (p && !strchr(p, '/')) {
+        Dl_info dlinfo;
+        if (dladdr(reinterpret_cast<void*>(addr), &dlinfo)) {
+           if ((strcmp(Module, dlinfo.dli_fname) == 0) && dlinfo.dli_fbase) {
+              unsigned long long base = reinterpret_cast<unsigned long long>(dlinfo.dli_fbase);
+              addr -= base;
+              addr &= 0x0FFFFFFFF; // to make it work on both 32 and 64 bit systems
+              }
+           }
+        }
+     }
   // determine the file name and line number:
-  cString cmd = cString::sprintf("addr2line --exe=%s --functions --demangle --basename %s", Module, Address);
+  cString cmd = cString::sprintf("addr2line --functions --demangle --inlines --basename --exe=%s 0x%llx", Module, Function ? addr : offs);
   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))
+              if (Function && strcmp(l, Function))
                  d = cString::sprintf("%s calling %s", *d, l);
               }
            else
@@ -494,101 +512,173 @@ static cString Demangle(char *s, char *Prefix = NULL)
            }
      p.Close();
      }
-  free(r);
+  free(DemangledFunction);
   return d;
 }
 
-static void BackTrace(void)
+void cBackTrace::BackTrace(cStringList &StringList, int Level, bool Mangled)
 {
   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]));
+     for (int i = max(Level, 0) + 1; i < n; i++) // 1 is the call to this function itself
+         StringList.Append(strdup(Mangled ? s[i] : *Demangle(s[i])));
      free(s);
      }
 }
 
-static void BackTraceCaller(int Level, char *t, int l)
+void cBackTrace::BackTrace(FILE *f, int Level, bool Mangled)
 {
+  cStringList sl;
+  BackTrace(sl, Level + 1, Mangled); // 1 is the call to this function itself
+  for (int i = 0; i < sl.Size(); i++) {
+      if (f)
+         fprintf(f, "%s\n", sl[i]);
+      else
+         dsyslog("%s", sl[i]);
+      }
+}
+
+cString cBackTrace::GetCaller(int Level, bool Mangled)
+{
+  cString Caller;
+  Level = max(Level, 0) + 1; // 1 is the call to this function itself
   void *b[BT_BUF_SIZE];
   int n = backtrace(b, BT_BUF_SIZE);
   if (char **s = backtrace_symbols(b, n)) {
-     strn0cpy(t, s[Level], l);
+     if (Level < n)
+        Caller = Mangled ? s[Level] : *Demangle(s[Level]);
      free(s);
      }
+  return Caller;
 }
 
-static void DumpStateLockLog(tThreadId ThreadId, const char *Name)
-{
-  if (!DumpStateLocks)
-     return;
-  DumpStateLocks = false;
+// --- cStateLockLog ---------------------------------------------------------
+
+#ifdef DEBUG_LOCKSEQ
+#define SLL_SIZE     20 // the number of log entries
+#define SLL_LENGTH  256 // the maximum length of log entries
+#define SLL_MAX_LIST  9 // max. number of lists to log
+#define SLL_WRITE_FLAG 0x80000000
+
+class cStateLockLog {
+private:
+  cMutex mutex;
+  cVector<tThreadId> threadIds;
+  cVector<int> flags;
+  tThreadId logThreadIds[SLL_SIZE];
+  int logFlags[SLL_SIZE];
+  char logCaller[SLL_SIZE][SLL_LENGTH];
+  int logIndex;
+  bool dumped;
+  void Dump(const char *Name, tThreadId ThreadId);
+public:
+  cStateLockLog(void);
+  void Check(const char *Name, bool Lock, bool Write = false);
+  };
+
+cStateLockLog::cStateLockLog(void)
+{
+  memset(logThreadIds, 0, sizeof(logThreadIds));
+  memset(logFlags, 0, sizeof(logFlags));
+  memset(logCaller, 0, sizeof(logCaller));
+  logIndex = 0;
+  dumped = false;
+}
+
+void cStateLockLog::Dump(const char *Name, tThreadId ThreadId)
+{
+  dsyslog("--- begin invalid lock sequence report");
+  int LastFlags = 0;
   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 (tThreadId tid = logThreadIds[logIndex]) {
+         char msg[SLL_LENGTH];
+         char *q = msg;
+         q += sprintf(q, "%5d", tid);
+         int Flags = logFlags[logIndex];
+         bool Write = Flags & SLL_WRITE_FLAG;
+         Flags &= ~SLL_WRITE_FLAG;
+         int Changed = LastFlags ^ Flags;
+         LastFlags = Flags;
+         bool Lock = (Flags & Changed) != 0;
+         for (int i = 0; i <= SLL_MAX_LIST; i++) {
+             char c = '-';
+             int b = 1 << i;
+             if ((Flags & b) != 0)
+                c = '*';
+             if ((Changed & b) != 0)
+                c = Lock ? Write ? 'W' : 'R' : '-';
+             q += sprintf(q, "  %c", c);
+             }
+         q += sprintf(q, "  %c", Lock ? 'L' : 'U');
+         if (*logCaller[logIndex]) {
+            *q++ = ' ';
+            strn0cpy(q, *cBackTrace::Demangle(logCaller[logIndex]), sizeof(msg) - (q - msg));
             }
+         dsyslog("%s", msg);
          }
-      if (++StateLockLogIndex >= SLL_SIZE)
-         StateLockLogIndex = 0;
+      if (++logIndex >= SLL_SIZE)
+         logIndex = 0;
       }
-  fprintf(stderr, "%5d invalid lock sequence: %-12s\n", ThreadId, Name);
-  fprintf(stderr, "full backtrace:\n");
-  BackTrace();
+  dsyslog("%5d invalid lock sequence: %s", ThreadId, Name);
+  dsyslog("full backtrace:");
+  cBackTrace::BackTrace(NULL, 2);
+  dsyslog("--- end invalid lock sequence report");
+  fprintf(stderr, "invalid lock sequence at %s\n", *DayDateTime(time(NULL)));
 }
 
-static void CheckStateLockLevel(const char *Name, bool Lock, bool Write = false)
+void cStateLockLog::Check(const char *Name, bool Lock, bool Write)
 {
-  if (Name) {
+  if (!dumped && Name) {
      int n = *Name - '0';
-     if (1 <= n && n <= 9) {
+     if (1 <= n && n <= SLL_MAX_LIST) {
         int b = 1 << (n - 1);
-        cMutexLock MutexLock(&StateLockMutex);
+        cMutexLock MutexLock(&mutex);
         tThreadId ThreadId = cThread::ThreadId();
-        int Index = StateLockThreadIds.IndexOf(ThreadId);
+        int Index = threadIds.IndexOf(ThreadId);
         if (Index < 0) {
            if (Lock) {
-              Index = StateLockThreadIds.Size();
-              StateLockThreadIds.Append(ThreadId);
-              StateLockFlags.Append(0);
+              Index = threadIds.Size();
+              threadIds.Append(ThreadId);
+              flags.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;
+        bool DoDump = false;
         if (Lock) {
-           if ((StateLockFlags[Index] & ~b) < b)
-              StateLockFlags[Index] |= b;
-           else if ((StateLockFlags[Index] & b) == 0)
-              DumpStateLockLog(ThreadId, Name);
+           if ((flags[Index] & ~b) < b) // thread holds only "smaller" locks -> OK
+              ;
+           else if ((flags[Index] & b) == 0) // thread already holds "bigger" locks, so it may only re-lock one that it already has!
+              DoDump = true;
+           flags[Index] |= b;
            }
         else
-           StateLockFlags[Index] &= ~b;
+           flags[Index] &= ~b;
+        logThreadIds[logIndex] = ThreadId;
+        logFlags[logIndex] = flags[Index] | (Write ? SLL_WRITE_FLAG : 0);
+#ifdef DEBUG_LOCKCALL
+        strn0cpy(logCaller[logIndex], cBackTrace::GetCaller(Lock ? 5 : 3, true), SLL_LENGTH);
+#endif
+        if (++logIndex >= SLL_SIZE)
+           logIndex = 0;
+        if (DoDump) {
+           Dump(Name, ThreadId);
+           dumped = true;
+           }
         }
      }
 }
-#define dbglockseq(n, l, w) CheckStateLockLevel(n, l, w)
+
+static cStateLockLog StateLockLog;
+
+#define dbglockseq(n, l, w) StateLockLog.Check(n, l, w)
 #else
 #define dbglockseq(n, l, w)
 #endif // DEBUG_LOCKSEQ
 
+// --- cStateLock ------------------------------------------------------------
+
 cStateLock::cStateLock(const char *Name)
 :rwLock(true)
 {