Random crash in sf2_player

[midi-pascal]

Branch: lmms-master, up to date
(Linux x86_64, Qt 4.8.6, GCC 4.8.4)
Ubuntu 14.04 x64 Core i5 8Gb ram

I already reported this problem in issue #2192 but it was occurring on my old box (a P4 with Ubuntu 12.04) and I thought it was because of a lack of hardware resources.
I am pretty well equipped now and the problem is still happening at a point that I cannot play a piece completely most of the time.
Note: this never occurs in stable-1.1 (1.1.3)

Steps to reproduce:
1- Start a new project
2- Import a Midi file with more than 10 tracks
3- Play

Lmms crashes randomly in sf2Instrument::noteOff() or sf2Instrument::noteOn() where the contents of the SF2PluginData* is totally corrupted:

Notes:

• The Midi file is not corrupted
• The crash does not occurs every time at the same place in the piece. Sometime at the very beginning, sometime later while playing.

A Midi file to reproduce can be found there:
http://jazzycat.tripod.com/tpspecl.mid

The backtrace I put in the other issue is still valid.

[michaelgregorius]

I have investigated the problem a bit. To narrow down the scope I started with turning SF2PluginData into a class and to make midiNote private. The reason is that midiNote shows problems above and that I wanted to gain as much control over changes to this variable as possible. I then added a constructor which takes the value for midiNote and adjusted the other code accordingly. In the constructor I added an assertion that makes sure that the value of midiNote is between 0 and 127. The assertion was never triggered so on construction all instances of SF2PluginData are fine (with regards to the MIDI note value). I also added getters and setters. I did not have to switch to using the setter anywhere in the code so the corruption also does not happen by setting a corrupt value later.

I have then added a check in sf2Instrument::noteOn which again checks for correct values of the MIDI note (because an assertion in fluid_synth_noteon was triggered). This check was triggered at a certain point when the song was playing. sf2Instrument::noteOn is called from sf2Instrument::play where we can find the following code which I think might be the cause of the problem:

SF2PluginData * currentData = static_cast<SF2PluginData *>( currentNote->m_pluginData );

If the void pointer m_pluginData does not point to an instance of SF2PluginData then some other data will be interpreted as a SF2PluginData which in turn will show bogus values as shown in the screenshot by @midi-pascal.

Heres my patch if you want to experiment yourself:

diff --git a/plugins/sf2_player/sf2_player.cpp b/plugins/sf2_player/sf2_player.cpp
index 07c4a0e..8c3d75a 100644
--- a/plugins/sf2_player/sf2_player.cpp
+++ b/plugins/sf2_player/sf2_player.cpp
@@ -43,6 +43,8 @@

 #include "embed.cpp"

+#include <cassert>
+

 extern "C"
 {
@@ -63,15 +65,32 @@ Plugin::Descriptor PLUGIN_EXPORT sf2player_plugin_descriptor =
 }


-struct SF2PluginData
+class SF2PluginData
 {
-   int midiNote;
+public:
+   SF2PluginData(int _midiNote) : midiNote(_midiNote)
+   {
+       bool noteInCorrectRange = (midiNote >= 0) && (midiNote <= 127);
+       assert(noteInCorrectRange);
+       if (!noteInCorrectRange)
+       {
+           // Add a line so we can add a breakpoint here...
+           int i = 0;
+       }
+   }
+
+   int getMidiNote() const { return midiNote; }
+   void setMidiNote(int _midiNote) { midiNote = _midiNote; }
+
    int lastPanning;
    float lastVelocity;
    fluid_voice_t * fluidVoice;
    bool isNew;
    f_cnt_t offset;
    bool noteOffSent;
+
+private:
+   int midiNote;
 } ;


@@ -556,8 +575,8 @@ void sf2Instrument::playNote( NotePlayHandle * _n, sampleFrame * )
        }
        const int baseVelocity = instrumentTrack()->midiPort()->baseVelocity();

-       SF2PluginData * pluginData = new SF2PluginData;
-       pluginData->midiNote = midiNote;
+       SF2PluginData * pluginData = new SF2PluginData(midiNote);
+       //pluginData->midiNote = midiNote;
        pluginData->lastPanning = 0;
        pluginData->lastVelocity = _n->midiVelocity( baseVelocity );
        pluginData->fluidVoice = NULL;
@@ -605,7 +624,12 @@ void sf2Instrument::noteOn( SF2PluginData * n )
        id[i] = fluid_voice_get_id( voices[i] );
    }

-   fluid_synth_noteon( m_synth, m_channel, n->midiNote, n->lastVelocity );
+   if (n->getMidiNote() < 0 || n->getMidiNote() > 127)
+   {
+       // Add a line so we can add a breakpoint here...
+       int i = 1;
+   }
+   fluid_synth_noteon( m_synth, m_channel, n->getMidiNote(), n->lastVelocity );

    // get new voice and save it
    fluid_synth_get_voicelist( m_synth, voices, poly, -1 );
@@ -622,7 +646,7 @@ void sf2Instrument::noteOn( SF2PluginData * n )
    m_synthMutex.unlock();

    m_notesRunningMutex.lock();
-   ++m_notesRunning[ n->midiNote ];
+   ++m_notesRunning[ n->getMidiNote() ];
    m_notesRunningMutex.unlock();
 }

@@ -631,13 +655,13 @@ void sf2Instrument::noteOff( SF2PluginData * n )
 {
    n->noteOffSent = true;
    m_notesRunningMutex.lock();
-   const int notes = --m_notesRunning[n->midiNote];
+   const int notes = --m_notesRunning[n->getMidiNote()];
    m_notesRunningMutex.unlock();

    if( notes <= 0 )
    {
        m_synthMutex.lock();
-       fluid_synth_noteoff( m_synth, m_channel, n->midiNote );
+       fluid_synth_noteoff( m_synth, m_channel, n->getMidiNote() );
        m_synthMutex.unlock();
    }   

[midi-pascal]

@michaelgregorius For sure I will try your patch 😄
It will help a lot to track the problem down - or up in this case - to its source.
I hate void* for this reason: it is really hard to decode their contents unless you are able to read a dump of hex values as easily as if it was regular text. This is not my greatest talent, I must say.

Thanks for your help!
I think we must fix this issue before 1.2 because it makes Lmms almost unusable with sf2 player...

[tresf]

Probably not related, but worth re-testing after this issue has been resolved: #649

[midi-pascal]

@michaelgregorius I think I found the problem but it looks so silly that I wonder if I am right or wrong...
In my early learning of C and C++ - long, long time ago -, my professors stressed a lot on us to add x = NULL; after a delete(x);
This is precisely what's happening there: the corrupted SF2PluginData was already freed so its access gives whatever the memory contains at this address at this moment.
For now I added the "magic" NULL assignment after the delete statement at some places in sf2_player.cpp and NotePlayHandle.cpp with the result of no more crash.

I would like a second advice on this because this seems a so basic programming flaw that I wonder if I am right...

[midi-pascal]

@tresf I don't think its related because this problem arises while playing the project, not while loading it as in # 649 (space added intentionally)

[midi-pascal]

@tresf May I suggest to escalate this issue as it breaks usability severely and tag it to 1.2?

[tresf]

Someone beat me to it. 👍

[Umcaruje]

Someone beat me to it. 👍

😉

[midi-pascal]

What a responsiveness! 😆
I am working on this issue.

[michaelgregorius]

@midi-pascal I think the pattern you have described is just used to make sure that a pointer is not deleted twice which would lead to a crash. For example executing this code would crash:

Foo *bar = new Foo();
delete bar; // Everything ok here
delete bar; // This will crash because the memory that bar points to has already been deleted

This code will not crash because calling delete 0 is legal in C++:

Foo *bar = new Foo();
delete bar; // Everything ok here
bar = 0;
delete bar; // Ok because delete 0 is legal

So I agree with @tresf that this is likely not the cause of the problem.

[midi-pascal]

@michaelgregorius I am aware of this and agree with your explanation of the crash on double delete() when the pointer is not set to NULL.
But the problem here is not caused by multiple deletions of the same object. It seems to be more complex than that.
As I can see it with the debugger, the pointer to the currentNote->m_pluginData is deleted in sf2Instrument::deleteNotePluginData().
The call sequence is:
0 sf2Instrument::deleteNotePluginData sf2_player.cpp 835 0x7fffae3451af
1 InstrumentTrack::deleteNotePluginData InstrumentTrack.cpp 489 0x600088
2 NotePlayHandle::done NotePlayHandle.cpp 149 0x527113
3 NotePlayHandleManager::release NotePlayHandle.cpp 610 0x528829
4 Mixer::renderNextBuffer Mixer.cpp 422 0x51eb9b
5 Mixer::fifoWriter::run Mixer.cpp 963 0x5202cb
...
After the call to delete(), the chunk of memory becomes available and may be reused elsewhere but the address remains valid and accessible (it is a static cast of a void* - Hell! -).
Hence the contents is not what is expected anymore.
The fact the crash occurs somewhat randomly enforce my feeling since the reuse of the free memory is somewhat not predictable.

In fact, the fundamental problem is: How these invalidated notes stay in m_playingNotes vector in sf2Instrument::play()?
I wrote a "filter" as a quick fix to remove these invalid notes from m_playingNotes before the normal processing. With the Midi file I use the filter removes between 1 to 7 of these notes during the playback.
The playback is ok: no notes missing, no sticky notes. It looks to me these invalid notes are reminiscent of notes already played, but I am not sure.
As for now I have not found how these notes are inserted in - or not removed from - the m_playingNotes vector.
With my "filter" Lmms does not crash anymore but the real cause of the problem is still to be found...

[michaelgregorius]

@midi-pascal I still believe that the crash is caused by pushing something that is not an SF2PluginData into the m_pluginData pointer somewhere.

Attached you can find another patch which seems to support this theory. It adds an std::set to sf2Instrument which stores the pointers of all SF2PluginDatas that are created. On deletion these pointers are removed from the set. Before each access to an instance of SF2PluginData a check is performed to see whether it is a known instance from the set. In case an unknown instance is found its content dumped to the console.

The patch also adds an extra check to make sure that all SF2PluginDatas are only deleted at the one known point where they are removed from the set as well (to prevent false alarms). This is the output that I got right before a crash:

"Unknown plugin data in sf2Instrument::play (currentData, second variable)" 
(isNew:  false , lastPanning:  32767 , lastVelocity:  54 , midiNote:  -738184768 , noteOffSent:  true , offset:  60 )

The warning is the one that is placed right after the aforementioned static_cast:

SF2PluginData * currentData = static_cast<SF2PluginData *>( currentNote->m_pluginData );

To me this is a strong indicator that something that is no SF2PluginData is cast to a SF2PluginData because all SF2PluginData that are created in sf2Instrument are placed into the set.

Here is the diff that can be used for debugging (please note that it does not include the other diff above):

diff --git a/plugins/sf2_player/sf2_player.cpp b/plugins/sf2_player/sf2_player.cpp
index 07c4a0e..f00c9c5 100644
--- a/plugins/sf2_player/sf2_player.cpp
+++ b/plugins/sf2_player/sf2_player.cpp
@@ -65,6 +65,25 @@ Plugin::Descriptor PLUGIN_EXPORT sf2player_plugin_descriptor =

 struct SF2PluginData
 {
+public:
+   SF2PluginData() :
+       midiNote(0),
+       lastPanning(0),
+       lastVelocity(0),
+       fluidVoice(0),
+       isNew(true),
+       offset(0),
+       noteOffSent(false),
+       aboutToBeDeletedAtAKnownPoint(false)
+   {}
+   ~SF2PluginData()
+   {
+       if (!aboutToBeDeletedAtAKnownPoint)
+       {
+           qDebug() << "SF2PluginData deleted at unknown point!";
+       }
+   }
+
    int midiNote;
    int lastPanning;
    float lastVelocity;
@@ -72,6 +91,7 @@ struct SF2PluginData
    bool isNew;
    f_cnt_t offset;
    bool noteOffSent;
+   bool aboutToBeDeletedAtAKnownPoint;
 } ;


@@ -260,6 +280,59 @@ QString sf2Instrument::nodeName() const



+void sf2Instrument::addToKnownSF2PluginDatas(SF2PluginData * sf2PluginData)
+{
+   if (!isKnownSF2PluginData(sf2PluginData))
+   {
+       QMutexLocker locker(&m_debugMutex);
+       m_knownSF2PluginDatas.insert(sf2PluginData);
+   }
+   else
+   {
+       qDebug() << "Known plugin data inserted again!";
+       dumpSF2PluginData(sf2PluginData);
+   }
+}
+
+void sf2Instrument::removeFromKnownSF2PluginDatas(SF2PluginData * sf2PluginData)
+{
+   if (isKnownSF2PluginData(sf2PluginData))
+   {
+       QMutexLocker locker(&m_debugMutex);
+       m_knownSF2PluginDatas.erase(sf2PluginData);
+   }
+   else
+   {
+       qDebug() << "Tried to remove an unknown plugin data!";
+       dumpSF2PluginData(sf2PluginData);
+   }
+}
+
+bool sf2Instrument::isKnownSF2PluginData(SF2PluginData * sf2PluginData)
+{
+   QMutexLocker locker(&m_debugMutex);
+   return m_knownSF2PluginDatas.find(sf2PluginData) != m_knownSF2PluginDatas.end();
+}
+
+void sf2Instrument::ensureKnownSF2PluginData(SF2PluginData * sf2PluginData, QString const & debugMessage)
+{
+   if (!isKnownSF2PluginData(sf2PluginData))
+   {
+       qDebug() << debugMessage;
+       dumpSF2PluginData(sf2PluginData);
+   }
+}
+
+void sf2Instrument::dumpSF2PluginData(SF2PluginData * sf2PluginData)
+{
+   qDebug() << "(isNew: " << sf2PluginData->isNew << ", lastPanning: " << sf2PluginData->lastPanning
+        << ", lastVelocity: " << sf2PluginData->lastVelocity
+        << ", midiNote: " << sf2PluginData->midiNote
+        << ", noteOffSent: " << sf2PluginData->noteOffSent
+        << ", offset: " << sf2PluginData->offset << ")";
+}
+
+

 void sf2Instrument::freeFont()
 {
@@ -557,6 +630,7 @@ void sf2Instrument::playNote( NotePlayHandle * _n, sampleFrame * )
        const int baseVelocity = instrumentTrack()->midiPort()->baseVelocity();

        SF2PluginData * pluginData = new SF2PluginData;
+       addToKnownSF2PluginDatas(pluginData);
        pluginData->midiNote = midiNote;
        pluginData->lastPanning = 0;
        pluginData->lastVelocity = _n->midiVelocity( baseVelocity );
@@ -575,6 +649,7 @@ void sf2Instrument::playNote( NotePlayHandle * _n, sampleFrame * )
    else if( _n->isReleased() ) // note is released during this period
    {
        SF2PluginData * pluginData = static_cast<SF2PluginData *>( _n->m_pluginData );
+       ensureKnownSF2PluginData(pluginData, "Unknown plugin data in sf2Instrument::playNote");
        pluginData->offset = _n->framesBeforeRelease();
        pluginData->isNew = false;

@@ -686,7 +761,11 @@ void sf2Instrument::play( sampleFrame * _working_buffer )
        for( int i = 1; i < m_playingNotes.size(); ++i )
        {
            SF2PluginData * currentData = static_cast<SF2PluginData *>( currentNote->m_pluginData );
+           ensureKnownSF2PluginData(currentData, "Unknown plugin data in sf2Instrument::play (currentData)");
+
            SF2PluginData * iData = static_cast<SF2PluginData *>( m_playingNotes[i]->m_pluginData );
+           ensureKnownSF2PluginData(iData, "Unknown plugin data in sf2Instrument::play (iData)");
+
            if( currentData->offset > iData->offset )
            {
                currentNote = m_playingNotes[i];
@@ -696,6 +775,8 @@ void sf2Instrument::play( sampleFrame * _working_buffer )
        // process the current note:
        // first see if we're synced in frame count
        SF2PluginData * currentData = static_cast<SF2PluginData *>( currentNote->m_pluginData );
+       ensureKnownSF2PluginData(currentData, "Unknown plugin data in sf2Instrument::play (currentData, second variable)");
+
        if( currentData->offset > currentFrame )
        {
            renderFrames( currentData->offset - currentFrame, _working_buffer + currentFrame );
@@ -776,11 +857,13 @@ void sf2Instrument::renderFrames( f_cnt_t frames, sampleFrame * buf )
 void sf2Instrument::deleteNotePluginData( NotePlayHandle * _n )
 {
    SF2PluginData * pluginData = static_cast<SF2PluginData *>( _n->m_pluginData );
+   removeFromKnownSF2PluginDatas(pluginData);
    if( ! pluginData->noteOffSent ) // if we for some reason haven't noteoffed the note before it gets deleted,
                                    // do it here
    {
        noteOff( pluginData );
    }
+   pluginData->aboutToBeDeletedAtAKnownPoint = true;
    delete pluginData;
 }

diff --git a/plugins/sf2_player/sf2_player.h b/plugins/sf2_player/sf2_player.h
index 2a6995c..155d91f 100644
--- a/plugins/sf2_player/sf2_player.h
+++ b/plugins/sf2_player/sf2_player.h
@@ -39,6 +39,8 @@
 #include "SampleBuffer.h"
 #include "MemoryManager.h"

+#include <set>
+
 class sf2InstrumentView;
 class sf2Font;
 class NotePlayHandle;
@@ -154,6 +156,14 @@ private:
    QVector<NotePlayHandle *> m_playingNotes;
    QMutex m_playingNotesMutex;

+   std::set<SF2PluginData*> m_knownSF2PluginDatas;
+   QMutex m_debugMutex;
+   void addToKnownSF2PluginDatas(SF2PluginData * sf2PluginData);
+   void removeFromKnownSF2PluginDatas(SF2PluginData * sf2PluginData);
+   bool isKnownSF2PluginData(SF2PluginData * sf2PluginData);
+   void ensureKnownSF2PluginData(SF2PluginData * sf2PluginData, QString const & debugMessage);
+   void dumpSF2PluginData(SF2PluginData * sf2PluginData);
+
 private:
    void freeFont();
    void noteOn( SF2PluginData * n );

[midi-pascal]

@michaelgregorius Thanks a lot for this. I will try it right now and let you know the results.
I was still searching for data corruption with no success so, I will get your point of view in further investigations.

[midi-pascal]

@michaelgregorius I tested your patch and it works well.
The origin of the issue is still to be found but I wonder if it is not located out of the sf2_player:
By going up the stack when the crash occurs I noticed that in InstrumentPlayHandle::play() the _working_buffer has strange (to me) contents when calling m_instrument->play( _working_buffer );

Is it possible that the issue originate from InstrumentPlayHandle, calling m_instrument->play() with some wrong values?
Are these negative values in _working_buffer ok?
I put a breakpoint at this line and the values are either 0 or positive when there is no crash.
I do not know this code enough to interpret them...
So, still stuck! 😦

[michaelgregorius]

@midi-pascal The patch above checks all accesses to m_pluginData so the data is very likely corrupted by some cause outside of sf2Instrument.

Another possible cause for the problem might be multithreading. When I was developing the patch I had a version that did not protect the accesses to m_knownSF2PluginDatas with mutexes and when running this version of the application I had also experienced crashes during the update of the set. So it seems that for some strange reason different threads manipulate the same instance(s) of sf2Instrument concurrently. In that case it would be very likely that other members get corrupted as well, e.g. m_playingNotes.

Please also note that in sf2Instrument::playNote the access to m_playingNotes is protected by m_playingNotesMutex while there is no such protection for the accesses in sf2Instrument::play. So the next thing we should do is to try whether the crashes still occur when these accesses are also protected by m_playingNotesMutex.

[midi-pascal]

@michaelgregorius I added m_playingNotesMutex.lock() and m_playingNotesMutex.unlock() around the whole while loop in sf2Instrument::play with no success. The crash occurs as often as before.
I tried some other things:

• I commented out delete pluginData; in sf2Instrument::deleteNotePluginData() . The result is no more crash! For sure this is not the right way to solve the issue since the pluginData's are not freed. Just a test.
• I added _n->m_pluginData = NULL; after delete pluginData; in sf2Instrument::deleteNotePluginData() and filtered notes with a NULL pluginData in sf2Instrument::play. The filter removes the notes from m_playingNotes and logs them before the main while loop.

So my main hypothesis are now:

• Some notes already played are re-introduced in - or not removed from - m_playingNotes. I can't figure how this could happen right now.
• sf2Instrument::deleteNotePluginData() is called for some notes that are not yet played. This could be a timing or thread synchronization problem since this method is called from the outside of sf2Instrument.

Note: By inspecting the notes that produce the crashes (or filtered out by my filter) I can see that faulty notes are always from the drums track. I believe this is not trivial: drums tracks have some simultaneous and very short notes. And faster the tempo, more faulty notes are produced for the same piece.
I will extract the drums track from my Midi file and try the piece without it and then try the drums track alone to see what happens.

[midi-pascal]

@michaelgregorius I tried the piece with no drums track: issue occurs in other tracks but less often. Then I tried the drums track alone: issue occurs but less often.
So I am clueless for now 😞

[midi-pascal]

@michaelgregorius Finally I found something interesting:
I put a trace in sf2Instrument::deleteNotePluginData() to check if the note processed there is an element of m_playingNotes. The answer is YES only when the crash occurs . This means deleteNotePluginData() is called before all the notes of m_playingNotes are processed by sf2Instrument::play.
In sf2Instrument::deleteNotePluginData() a noteOff() is sent but the note is not removed from m_playingNotes if it is in it.
By adding:
if( m_playingNotes.indexOf( _n ) >= 0 )
{
m_playingNotesMutex.lock();
m_playingNotes.remove( m_playingNotes.indexOf( _n ) );
m_playingNotesMutex.unlock();
}
after the call to noteOff( pluginData ); the crash does not occurs.
I have no idea how or why sf2Instrument::deleteNotePluginData() is called before all the notes are processed by sf2Instrument::play though.
Do you think this fix is appropriate to solve the issue?
If not, I am not sure I can investigate further since this looks like a synchronization issue between threads, a subject I am not mastering enough.

[musikBear]

do not know if this is useful at all, but i have the same result on
xp-sp3 Master from 14. juli
Lmms froze during the 11th looped play of tpspecl.mid

[midi-pascal]

I found what causes the crash and made a patch that solves it. However I do not understand why the problem occurs because my knowledge of Lmms inside working is still far from good. May I ask for a second look on what I did from a more knowledgeable person before I submit a PR for it? Thanks.

[michaelgregorius]

@midi-pascal I think the most straight forward way for others to inspect your changes would be to create a pull request with them. If the review would find that everything was fine then it could be merged immediately. If for some reason the problem would not not be solved by the pull request you could simply delete it.

Another thing that I have thought of is that it might be helpful to extend SF2PluginData (or NotePlayHandle) with some information about which actions were performed by which thread. Because it would be only used for cause analysis one might for example store the Qt::HANDLE returned by QThread::currentThreadId() and then compare which thread deleted a SF2PluginData and which thread is still consuming them.

[midi-pascal]

@michaelgregorius I submited a pull request few minutes ago (#2422) so my changes can be reviewed by everybody. For sure this patch solves the issue but not its cause. This is why I asked for a 'master' 😄