VDR Crash, wenn Abspielen und Stopp einer Aufnahme zu nah bei einander liegen

seahawk1986 · May 15, 2020 at 1:01 PM

Hallo,

mir ist beim Herumspielen mit einer VueJS-Komponente fürs yavdr-Webfrontend eine Race-Condition aufgefallen, wenn man eine Aufnahme abspielten lässt und zeitnah jemand die Stop-Taste drückt.

Nachdem ich erst an einen Patch als Ursache gedacht hatte, habe ich es mit der Minimal-Variante (ungepatchter VDR mit einem Ausgabeplugin (noop-Ausgabe, um es einfacher zu machen)) probiert:

Code

$ ./vdr -c /etc/vdr/ -v /srv/vdr/video/ -l3 "-Psofthddevice -vnoop -d :0"
double free or corruption (out)
Abgebrochen (Speicherabzug geschrieben)

Ich kann das meist schon nach einer Hand voll abgespielten Aufnahmen provozieren, wenn ich zwei svdrp-Befehle in zwei parallellen Endlosschleifen (geht z.B. mit tmux bequem über ein SSH-Session) laufen lasse:

Code: Endlosschleife 1

while :
do
    svdrpsend HITK STOP
done

Code: Endlosschleife 2

while :
do
    while read -r rec_id
    do
        svdrpsend play "$rec_id"; sleep 0.$(( RANDOM % 10 ))
    done < <(svdrpsend lstr | grep -Po "(?<=250-)\d+" | shuf)
done

Einen vollständigen Backtrace vom Crash habe ich angehängt: vdr-backtrace.txt

Im Thread 36 sieht es so aus, als ob da Destruktoren mehrfach aufgerufen werden:

Code

Thread 36 (Thread 0x7fffb27fc700 (LWP 2604)):
#0  0x00007ffff78fb18b in raise () at /lib/x86_64-linux-gnu/libc.so.6
#1  0x00007ffff78da859 in abort () at /lib/x86_64-linux-gnu/libc.so.6
#2  0x00007ffff79453ee in  () at /lib/x86_64-linux-gnu/libc.so.6
#3  0x00007ffff794d47c in  () at /lib/x86_64-linux-gnu/libc.so.6
#4  0x00007ffff794f120 in  () at /lib/x86_64-linux-gnu/libc.so.6
#5  0x000055555567fd21 in cIndexFile::~cIndexFile() (this=0x7fff9c070340, __in_chrg=<optimized out>) at recording.c:2614
#6  0x00005555556238c6 in cDvbPlayer::~cDvbPlayer() (this=0x7fff9c06b0a0, __in_chrg=<optimized out>) at dvbplayer.c:342
#7  0x00005555556247aa in cDvbPlayer::~cDvbPlayer() (this=0x7fff9c06b0a0, __in_chrg=<optimized out>) at dvbplayer.c:337
#8  cDvbPlayerControl::Stop() (this=this@entry=0x7fff9c000e90) at dvbplayer.c:1007
#9  0x00005555556523b8 in cReplayControl::Stop() (this=0x7fff9c000e90) at menu.c:5661
#10 0x0000555555652512 in cReplayControl::~cReplayControl() (this=0x7fff9c000e90, __in_chrg=<optimized out>) at menu.c:5614
#11 0x000055555565259d in cReplayControl::~cReplayControl() (this=0x7fff9c000e90, __in_chrg=<optimized out>) at menu.c:5611
#12 0x00005555556741e7 in cControl::Shutdown() () at player.c:105
        MutexLock = {mutex = 0x555555795300 <cControl::mutex>, locked = true}
        c = <optimized out>
#13 0x00005555556ae55e in cSVDRPServer::CmdPLAY(char const*) (this=0x7fff9c003880, Option=<optimized out>) at svdrp.c:2262
        FileName = {_vptr.cString = 0x555555737d38 <vtable for cString+16>, s = 0x7fff9c0724a0 "/srv/vdr/video/local/Covid-19_Spezial_vom_27.4.2020/2020-04-28.15.43.10-0.rec"}
        Title = {_vptr.cString = 0x555555737d38 <vtable for cString+16>, s = 0x7fff9c00fb10 "28.04.20 15:43  local~Covid-19 Spezial vom 27.4.2020"}
        FramesPerSecond = 50
        IsPesRecording = false
        Recording = <optimized out>
        StateKey = {stateLock = 0x0, write = false, state = 25, timedOut = false}
        opt = 0x7fff9c069060 "1"
        num = 0x7fff9c069060 "1"
        option = 0x7fff9c069061 ""
        c = 0 '\000'
#14 0x00005555556b0f92 in cSVDRPServer::Process() (this=0x7fff9c003880) at svdrp.c:2621
        c = 10 '\n'
        r = <optimized out>
#15 0x00005555556b1220 in cSVDRPServerHandler::ProcessConnections() (this=0x5555559d2330) at svdrp.c:2725
        i = 0
#16 0x00005555556b1435 in cSVDRPServerHandler::Action() (this=0x5555559d2330) at svdrp.c:2749
#17 0x00005555556b3765 in cThread::StartThread(cThread*) (Thread=0x5555559d2330) at thread.c:293
#18 0x00007ffff7f12609 in start_thread () at /lib/x86_64-linux-gnu/libpthread.so.0
#19 0x00007ffff79d7103 in clone () at /lib/x86_64-linux-gnu/libc.so.6

Display More

kls · May 15, 2020 at 3:33 PM

Kannst du bitte noch die Logfile-Einträge posten vom Start der vorletzten Wiedergabe bis zum Crash?

<edit>

Bitte vom Start der *vor*letzten Wiedergabe bis zum Crash.

</edit>

seahawk1986 · May 15, 2020 at 4:44 PM

Ich habe noch mal alles neu erzeigt und dafür noch ein paar Log-Warnungen von softhddevice per workaround-Schalter eliminiert - der Aufruf sah jetzt so aus:

# gdb --args ./vdr -c /etc/vdr/ -v /srv/vdr/video/ -u vdr -l3 "-Psofthddevice -d :0 -vnoop -a pulse -w alsa-driver-broken"

softhddevice ist aus diesem Git-Repository: https://github.com/ua0lnj/vdr-plugin-softhddevice

vdr.log.txt

backtrace.txt

kls · May 15, 2020 at 5:07 PM

Bitte teste mal mit diesem Patch und poste wieder die Log-Ausgaben (den Backtrace brauche ich momentan nicht).

Wenn du magst können wir auch gerne per Email weitermachen, um hier nicht zuviel Noise zu verursachen.

mini73 · May 15, 2020 at 5:08 PM

Ich finde den Noise interessant.

kls · May 15, 2020 at 5:08 PM

OK, dann machen wir hier weiter ;-).

seahawk1986 · May 15, 2020 at 5:19 PM

Damit sieht es so aus:

vdr.log.txt

vdr-backtrace.txt

kls · May 15, 2020 at 5:23 PM

Der index wird also von zwei Threads gelöscht. Sollte eigentlich nicht passieren, aber anscheinend fehlt da noch eine Verriegelung.
Schauen wir erstmal, ob beiliegende Änderung was bewirkt.

seahawk1986 · May 15, 2020 at 5:30 PM

Damit sieht es beim Crash so aus:

vdr-dbg-double-free-002.log.txt

vdr-dbg-double-free-002.backtrace.txt

kls · May 15, 2020 at 5:47 PM

Nächster Schritt...

seahawk1986 · May 15, 2020 at 5:59 PM

Damit sieht es so aus:

vdr-2.4.1-dbg-double-free-index-03.log.txt

vdr-2.4.1-dbg-double-free-index-03.backtrace.txt

kls · May 15, 2020 at 6:20 PM

Voraussichtlich letzter Schritt für heute.

seahawk1986 · May 15, 2020 at 6:29 PM

Mit dem Patch baut der VDR leider nicht, die Fehlermeldung sieht so aus:

Code

$ make
CC dvbplayer.o
CC menu.o
CC player.o
In file included from i18n.h:14,
                 from config.h:19,
                 from channels.h:13,
                 from device.h:13,
                 from player.h:13,
                 from player.c:10:
player.c: In static member function 'static void cControl::Shutdown()':
player.c:102:48: error: 'this' is unavailable for static member functions
  102 |   dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
      |                                                ^~~~
tools.h:37:76: note: in definition of macro 'dsyslog'
   37 | #define dsyslog(a...) void( (SysLogLevel > 2) ? syslog_with_tid(LOG_DEBUG, a) : void() )
      |                                                                            ^
player.c:104:59: error: 'this' is unavailable for static member functions
  104 |   dsyslog("%s %d this=%p control=%p", __FILE__, __LINE__, this, control);//XXX
      |                                                           ^~~~
tools.h:37:76: note: in definition of macro 'dsyslog'
   37 | #define dsyslog(a...) void( (SysLogLevel > 2) ? syslog_with_tid(LOG_DEBUG, a) : void() )
      |                                                                            ^
player.c:107:48: error: 'this' is unavailable for static member functions
  107 |   dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
      |                                                ^~~~
tools.h:37:76: note: in definition of macro 'dsyslog'
   37 | #define dsyslog(a...) void( (SysLogLevel > 2) ? syslog_with_tid(LOG_DEBUG, a) : void() )
      |                                                                            ^
player.c:109:48: error: 'this' is unavailable for static member functions
  109 |   dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
      |                                                ^~~~
tools.h:37:76: note: in definition of macro 'dsyslog'
   37 | #define dsyslog(a...) void( (SysLogLevel > 2) ? syslog_with_tid(LOG_DEBUG, a) : void() )
      |                                                                            ^
make: *** [Makefile:134: player.o] Fehler 1

Display More

mini73 · May 15, 2020 at 6:54 PM

Dann einfach das this=%p aus dem String weglassen und hinten den Parameter auch.

mini73 · May 15, 2020 at 6:56 PM

Oder statt this evtl. control nehmen, wo es passt. Um den Pointer geht es da vermutlich.

seahawk1986 · May 15, 2020 at 7:02 PM

Wenn ich den Patch so

Diff

diff --git a/dvbplayer.c b/dvbplayer.c
index 33c992b..26f1b17 100644
--- a/dvbplayer.c
+++ b/dvbplayer.c
@@ -987,7 +987,9 @@ cDvbPlayerControl::cDvbPlayerControl(const char *FileName, bool PauseLive)

 cDvbPlayerControl::~cDvbPlayerControl()
 {
+  dsyslog("%s %d this=%p player=%p", __FILE__, __LINE__, this, player);//XXX
   Stop();
+  dsyslog("%s %d this=%p player=%p", __FILE__, __LINE__, this, player);//XXX
 }

 void cDvbPlayerControl::SetMarks(const cMarks *Marks)
@@ -1004,8 +1006,11 @@ bool cDvbPlayerControl::Active(void)
 void cDvbPlayerControl::Stop(void)
 {
   cControl::player = NULL;
+  dsyslog("%s %d this=%p player=%p", __FILE__, __LINE__, this, player);//XXX
   delete player;
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
   player = NULL;
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
 }

 void cDvbPlayerControl::Pause(void)
diff --git a/menu.c b/menu.c
index 58c7763..9518a0e 100644
--- a/menu.c
+++ b/menu.c
@@ -5611,13 +5611,16 @@ cReplayControl::cReplayControl(bool PauseLive)
 cReplayControl::~cReplayControl()
 {
   cDevice::PrimaryDevice()->SetKeepTracks(false);
+  dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
   Stop();
+  dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
   if (currentReplayControl == this)
      currentReplayControl = NULL;
 }

 void cReplayControl::Stop(void)
 {
+  dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
   Hide();
   cStatus::MsgReplaying(this, NULL, fileName, false);
   if (Setup.DelTimeshiftRec && *fileName) {
@@ -5636,7 +5639,9 @@ void cReplayControl::Stop(void)
                    isyslog("deleted timer %s", *Timer->ToDescr());
                    }
               }
+              dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
               cDvbPlayerControl::Stop();
+              dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
               bool Error = false;
               {
                 LOCK_RECORDINGS_WRITE;
@@ -5658,7 +5663,9 @@ void cReplayControl::Stop(void)
            }
         }
      }
+  dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
   cDvbPlayerControl::Stop();
+  dsyslog("%s %d this=%p", __FILE__, __LINE__, this);//XXX
   cMenuRecordings::SetRecording(NULL); // make sure opening the Recordings menu navigates to the last replayed recording
 }

diff --git a/player.c b/player.c
index 5c95f4e..899029c 100644
--- a/player.c
+++ b/player.c
@@ -99,8 +99,12 @@ void cControl::Attach(void)

 void cControl::Shutdown(void)
 {
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
   cMutexLock MutexLock(&mutex);
+  dsyslog("%s %d control=%p", __FILE__, __LINE__, control);//XXX
   cControl *c = control; // avoids recursions
   control = NULL;
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
   delete c;
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
 }
diff --git a/recording.c b/recording.c
index 810ef80..df727b6 100644
--- a/recording.c
+++ b/recording.c
@@ -2611,7 +2611,10 @@ cIndexFile::~cIndexFile()
 {
   if (f >= 0)
      close(f);
+  dsyslog("%s %d this=%p index=%p", __FILE__, __LINE__, this, index);//XXX
   free(index);
+  index = NULL;
+  dsyslog("%s %d", __FILE__, __LINE__);//XXX
   delete indexFileGenerator;
 }

Display More

abändere, sieht es so aus:

vdr-2.4.1-dbg-double-free-index-04.log.txt

vdr-2.4.1-dbg-double-free-index-04.backrace.txt

kls · May 15, 2020 at 7:02 PM

Sorry, da hatte ich den Diff vor der letzten Änderung gemacht.

Hier nochmal.

kls · May 15, 2020 at 7:03 PM

OK, da warst du schneller als ich.

Ich kann aber erst morgen weitermachen.

kls · May 16, 2020 at 11:49 AM

Momentaner Erkenntnisstand:

cSVDRPServer::CmdPLAY() ruft cControl::Shutdown() auf, zu einer Zeit, wo sich die Hauptschleife in main() mit

Interact = Menu ? Menu : cControl::Control();

das Control geholt hat und im weiteren Verlauf auf das "HITK STOP" reagiert.

Der cControl::Shutdown() im SVDRP-Thread zerstört das Control, das main() weiterhin verwednet.

Das hat früher nicht passieren können, da SVDRP-Befehle nicht in einem separaten Thread verarbeitet wurden. Auch jetzt kann es wohl nur in solchen extremen Situationen auftreten, was aber natürlich keine Entschuldigung für ein fehlendes Locking sein kann.

Ich überlege mir, wie sich das lösen lässt...

kls · May 16, 2020 at 4:58 PM

Anbei ein erster Versuch, cControl::Control() mit Locks zu versehen.

Nur mal als proof-of-concept.

Participate now!