Crash cleaning up mutexes

[joshaber]

From atom/atom#10445 (comment):

abort() called

Thread 0 Crashed:: CrRendererMain  Dispatch queue: com.apple.main-thread
0   libsystem_kernel.dylib          0x00007fff8de9d286 __pthread_kill + 10
1   libsystem_c.dylib               0x00007fff8b7da9b3 abort + 129
2   libnode.dylib                   0x000000010553da54 uv_mutex_destroy + 20
3   nodegit.node                    0x000000011002dd80 LockMasterImpl::CleanupMutexes(uv_async_s*) + 72
4   libnode.dylib                   0x000000010553461b 0x1053f4000 + 1312283

...

Thread 12:
0   libsystem_c.dylib               0x00007fff8b7d79ef strncasecmp_l + 84
1   nodegit.node                    0x00000001101cd763 git_index_entry_isrch + 47
2   nodegit.node                    0x000000011021476a git__bsearch + 67
3   nodegit.node                    0x00000001101d2708 git_index_snapshot_find + 73
4   nodegit.node                    0x00000001101d64fe workdir_iterator__enter_dir + 441
5   nodegit.node                    0x00000001101d70fa fs_iterator__expand_dir + 1050
6   nodegit.node                    0x00000001101d5e1b fs_iterator__advance_into + 67
7   nodegit.node                    0x00000001101bc073 git_diff__from_iterators + 2156
8   nodegit.node                    0x00000001101bcfa3 git_diff_index_to_workdir + 219
9   nodegit.node                    0x000000011020d79c git_submodule__status + 754
10  nodegit.node                    0x00000001101bc53a git_diff__from_iterators + 3379
11  nodegit.node                    0x00000001101bcfa3 git_diff_index_to_workdir + 219
12  nodegit.node                    0x000000011020973a git_status_list_new + 930
13  nodegit.node                    0x000000011016df9f GitStatusList::CreateWorker::Execute() + 67
14  libnode.dylib                   0x0000000105532d2e 0x1053f4000 + 1305902

...

Thread 13:
0   libsystem_kernel.dylib          0x00007fff8de9d14e __psynch_mutexdrop + 10
1   libnode.dylib                   0x000000010553dab9 uv_mutex_unlock + 9
2   nodegit.node                    0x000000011002deb5 LockMasterImpl::GetMutexes(int) + 227
3   nodegit.node                    0x000000011002e024 LockMasterImpl::Unlock(bool) + 38
4   nodegit.node                    0x000000011002e5e3 LockMasterImpl::~LockMasterImpl() + 37
5   nodegit.node                    0x000000011002e10e LockMaster::DestructorImpl() + 22
6   nodegit.node                    0x000000011003e0af LockMaster::~LockMaster() + 15
7   nodegit.node                    0x000000011011486f GitRefs::DwimWorker::Execute() + 123
8   libnode.dylib                   0x0000000105532d2e 0x1053f4000 + 1305902

...

Thread 14:
0   libsystem_kernel.dylib          0x00007fff8de9e2f2 lstat$INODE64 + 10
1   nodegit.node                    0x00000001101d6f48 fs_iterator__expand_dir + 616
2   nodegit.node                    0x00000001101d5e1b fs_iterator__advance_into + 67
3   nodegit.node                    0x00000001101bc073 git_diff__from_iterators + 2156
4   nodegit.node                    0x00000001101bcfa3 git_diff_index_to_workdir + 219
5   nodegit.node                    0x000000011020973a git_status_list_new + 930
6   nodegit.node                    0x000000011016df9f GitStatusList::CreateWorker::Execute() + 67
7   libnode.dylib                   0x0000000105532d2e 0x1053f4000 + 1305902

...

Thread 15:
0   libsystem_kernel.dylib          0x00007fff8de9d166 __psynch_mutexwait + 10
1   libnode.dylib                   0x000000010553da69 uv_mutex_lock + 9
2   nodegit.node                    0x000000011002dfa5 LockMasterImpl::Lock(bool) + 151
3   nodegit.node                    0x000000011011481f GitRefs::DwimWorker::Execute() + 43
4   libnode.dylib                   0x0000000105532d2e 0x1053f4000 + 1305902

/cc @srajko

[srajko]

Tnx, taking a look right now.

[srajko]

Just dumping what I found so far, in case anyone else is looking at this.

Based on the crash log, the threads in LockMaster are in these places:
Thread 0 -

nodegit/generate/templates/manual/src/lock_master.cc

Line 100 in ab27f65

uv_mutex_destroy(mutex);

Thread 13 -

nodegit/generate/templates/manual/src/lock_master.cc

Line 141 in ab27f65

uv_mutex_unlock(&mapMutex);

Thread 15 -

nodegit/generate/templates/manual/src/lock_master.cc

Line 180 in ab27f65

uv_mutex_lock(*it);

So the first thread is crashing on destroying a mutex, the second thread is unlocking or has just unlocked mapMutex (and by the fact that the first thread is in its critical section protected by mapMutex, I'll guess that the second thread has just unlocked it), and the third thread is waiting to lock a mutex that it couldn't lock via uv_mutex_trylock.

The locking/unlocking calls are for dwim (https://libgit2.github.com/libgit2/#v0.23.4/group/reference/git_reference_dwim), which should only be locking on the git_repository. Also, dwim doesn't use any callback parameters, so TemporaryUnlock doesn't come into play, at least not for these use cases (it's still possible that the mutex crashing on destruction was touched by TemporaryUnlock).

Looking at uv_mutex_destroy (https://github.com/libuv/libuv/blob/3db07cc379a881d942eef6d2248afaef89a8857a/src/unix/thread.c#L141-L144), it calls abort if pthread_mutex_destroy returns an error, and that happens in the following cases:

[EBUSY]
 The implementation has detected an attempt to destroy the object referenced by mutex while it is
 locked or referenced (for example, while being used in a pthread_cond_timedwait() or
 pthread_cond_wait()) by another thread.
[EINVAL]
 The value specified by mutex is invalid.

This all hasn't lead me to any smoking guns yet, still looking.

[srajko]

Looking at the remaining two threads (12 and 14), they are in GitStatusList::CreateWorker::Execute (calling git_status_list_new - https://libgit2.github.com/libgit2/#v0.23.4/group/status/git_status_list_new).

Each one of those should have a repository locked. The generated source for GitStatusList::CreateWorker::Execute confirms this.

@joshaber does atom work on multiple repos at the same time? (asking just for sanity-check sake)

[joshaber]

Hmm. It shouldn't be, but I couldn't rule it out. This code is all pretty new.

Could this be #863? There hasn't been a release out with that fix AFAIK.

[tbranyen]

If you can reproduce the issue @joshaber, maybe you can pull the latest master commit and try that?

[srajko]

That should be in d358ab1

OK I did find something that looks fishy:

nodegit/generate/templates/manual/src/lock_master.cc

Line 176 in ab27f65

if (alreadyLocked > it && alreadyLocked != objectMutexes.end()) {

I think that should be alreadyLocked >= it, not alreadyLocked > it, because the previous line:

std::for_each(objectMutexes.begin(), it, uv_mutex_unlock);

unlocks everything up to but not including it. The next line is supposed to unlock the alreadyLocked mutex if it wasn't covered by the std::for_each.

So let's see... with the code as-is, suppose we are locking something that requires two locks, and this happens:

We get to this code, which tries to lock everything at once. It tries to lock the first mutex, succeeds. It tries to lock the second mutex, the try fails, it releases the first mutex and it goes into the blocking uv_mutex_lock for the second mutex. It eventually locks the mutex, and marks it as alreadyLocked.

It now goes back to trying to lock everything (else). It tries to lock the first mutex, fails. The faulty code is supposed to release the second mutex, but doesn't. It then does a blocking uv_mutex_lock on the first mutex, eventually locks it, and marks it as alreadyLocked.

It again goes back to trying to lock everything (else). That's just the second mutex. I'm a little uncertain as to what happens next, and it also seems like it's platform-specific. When it tries to lock the second mutex (which already got locked at some point, but erroneously not released), it might crash or deadlock (if the platform doesn't support recursive mutexes), or it might go ahead but mark the mutex as twice-locked.

Eventually, we release that mutex, but only once, and because it was locked twice pthreads returns an error on destroy.

So, I'll go with the following:

• it is possible that this caused the crash in question, but hell if I know :-)
• the code definitely looks wrong, so I'll PR a fix... and we hope?

It would be nice to get some testing into this at the c++ level. Anyone know any good ways to incorporate native testing with native node modules? :-)

[srajko]

Nope, I think that's faulty... it refers to the mutex we just tried to lock, but failed. So we do want to skip unlocking this mutex (and > is correct)

Here:

It now goes back to trying to lock everything (else). It tries to lock the first mutex, fails. The faulty code is supposed to release the second mutex, but doesn't.

when it tries to lock the first mutex, it refers to the first mutex, the second mutex satisfies the > condition and does in fact get unlocked. The code above:

if (it == alreadyLocked) {
  continue;
}

actually guarantees that it is never == alreadyLocked by the time we get to that > check. So #871 would make no difference.

[srajko]

I found this library - https://github.com/smikes/CppUnitLite - and was able to get some c++ unit tests going. I'll keep expanding the tests, hopefully something sheds light on this crash.

@joshaber how critical is this issue in atom? Is this in production?

[joshaber]

We don't yet have a release out which includes nodegit. One of the members of our core team got that from a local build.

[joshaber]

does atom work on multiple repos at the same time? (asking just for sanity-check sake)

Thinking about this... Should this matter? The locks, etc. would be independent per repo.

[joshaber]

Alright so here are some thoughts. I'd love a second set of 👀s and 👂s.

Unlocking looks like this:

void LockMasterImpl::Unlock(bool releaseMutexes) {
  std::vector<uv_mutex_t *> objectMutexes = GetMutexes(releaseMutexes * -1);

  std::for_each(objectMutexes.begin(), objectMutexes.end(), uv_mutex_unlock);
}

At the point between GetMutexes and the completion of std::for_each, the useCount for each of the objectMutexes is 0, but they haven't all been unlocked, and they aren't protected by any lock. So if CleanupMutexes gets called during that, it could try to destroy a mutex which is still unlocked/being unlocked.

I think that's possible and wrong. We should only decrement the useCount after the mutex has been unlocked.

@srajko What do you think? Am I missing something?

[srajko]

We don't yet have a release out which includes nodegit. One of the members of our core team got that from a local build.

Phew, that makes me feel better :-)

does atom work on multiple repos at the same time? (asking just for sanity-check sake)

Thinking about this... Should this matter? The locks, etc. would be independent per repo.

It shouldn't matter - I was just wondering while making sense of the crash log. If it's only accessing one repository, then two libgit2 functions operating simultaneously on the same repo would mean there is a bug somewhere. It wouldn't necessarily be related to the crash, just a possible separate concern.

I think that's possible and wrong. We should only decrement the useCount after the mutex has been unlocked.

Nice!!! That is definitely a problem. And looking back at the crash log, it would explain it - because thread 13 has already finished with all the code within GetMutexes (and it's within an Unlock call), and exactly as you point out - the use counts would already be decremented, but the mutexes are still in use, and CleanupMutexes trying to destroy them would crash... as it did

Thanks for catching that @joshaber! Did you want to PR a fix for that? I can give it a go tonight otherwise.