open enclave dead lock

[wodadehencou]

Describe the bug
Open enclave may cause RWMutex lock, caused by recursive rlock the RWMutex which is not permitted by golang.

in file: src/sync/rwmutex.go

// If a goroutine holds a RWMutex for reading and another goroutine might
// call Lock, no goroutine should expect to be able to acquire a read lock
// until the initial read lock is released. In particular, this prohibits
// recursive read locking. This is to ensure that the lock eventually becomes
// available; a blocked Lock call excludes new readers from acquiring the
// lock

To Reproduce
Steps to reproduce the behaviour:

1. create a testcase that open the enclave parallel, maybe 20 goroutines.
2. the process will locked in about 5 minutes, at Rlock() in func (s *Coffer) Destroyed() bool {
3. this problem occurs in OSX and Linux

Expected behaviour
all process run normally

Screenshots
If applicable, add screenshots to help explain your problem.

System (please complete the following information):

• OS and Kernel Versions: OSX 10.15
• Memguard Version: v0.19.1 & v0.22.1
• Go Version: go1.12 & go1.14

Additional context
Use testcase below can generate the case. CPU usage start at about 100%, then decrease to 0%. now the process is locked.

package main

import (
	"bytes"
	"context"
	"crypto/rand"
	"errors"
	"fmt"
	"io"
	"os"
	"os/signal"
	"syscall"
	"time"

	"github.com/awnumar/memguard"
)

func main() {
	sigs := make(chan os.Signal, 1)
	signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM)

	ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute)
	go func() {
		select {
		case <-sigs:
			cancel()
		}
	}()
	OpenEnclave(ctx)
}

func OpenEnclave(ctx context.Context) {
	n := 10
	data := make([][]byte, n)
	enclaves := make([]*memguard.Enclave, n)
	for i := range data {
		data[i] = make([]byte, 32)
		buf := make([]byte, 32)
		io.ReadFull(rand.Reader, buf)
		copy(data[i], buf)
		enclaves[i] = memguard.NewEnclave(buf)
	}

	threads := 20
	for i := 0; i < threads; i++ {
		j := 0
		go func(ctx context.Context) {
			for {
				select {
				case <-ctx.Done():
					return
				default:
					{
						// fmt.Printf("open enclave %d \n", j)
						immediateOpen(ctx, enclaves[j], data[j])
						j = (j + 1) % n
					}
				}
			}
		}(ctx)
	}
	<-ctx.Done()
	time.Sleep(time.Second)
}

func openVerify(lock *memguard.Enclave, exp []byte) error {
	lb, err := lock.Open()
	if err != nil {
		return err
	}
	defer lb.Destroy()
	if !bytes.Equal(lb.Bytes(), exp) {
		return errors.New("open verify fail")
	}
	return nil
}

func immediateOpen(ctx context.Context, lock *memguard.Enclave, exp []byte) {
	start := time.Now()
	c1 := make(chan error, 1)
	go func() {
		err := openVerify(lock, exp)
		c1 <- err
	}()
	var dur time.Duration
	select {
	case err := <-c1:
		{
			dur = time.Since(start)
			if err != nil {
				fmt.Printf("### open fail: %s \n", err)
			}
		}
	case <-ctx.Done():
		{
			dur = time.Since(start)
			fmt.Printf("### timeout \n")
		}
	}
	// fmt.Printf("%d, %d \n", start.UnixNano(), dur.Nanoseconds())
	_ = dur
}

[awnumar]

Thanks for reporting. 👍

[awnumar]

After applying the patch the behaviour seems identical. A bunch of timeouts after a period:

...
1587048652522845416, 36642766 
1587048652555571711, 3972773 
1587048652544642401, 14974528 
1587048652555173078, 4526586 
^C### timeout 
1587048652559703689, 27796593682 
### timeout 
1587048652559624289, 27796714889 
### timeout 
1587048652559552655, 27796801999 
...

[wodadehencou]

I can not get the problem on my platform (go1.14, OSX), could you @awnumar please add two lines codes at the end of function OpenEnclave, print out the stack information.

         // ...
	<-ctx.Done()
	time.Sleep(time.Second)

	buf := make([]byte, 1<<20)
	fmt.Println(string(buf[:runtime.Stack(buf, true)])
}

I read all the codes of memguard, there are some other place have the same bug, I will make a MR as soon as possible

[awnumar]

Here's the output: trace.txt
go version go1.14.2 linux/amd64

[wodadehencou]

This is because the Purge() function, operation flow is
enclave.Open -> Key.View --(get RLock)--> NewBuffer -> memcall.Alloc[Fail] -> Panic -> Purge -> key.Lock (request write lock)

This is another dead lock case.
But I don't know why in your @awnumar system, memcall.Alloc was fail

A simple solution for all these dead lock cases, is to arrange all the Lock() & UnLock() carefully. But it will be less efficient, there will be more than ONE lock in a few of continuous operations.

[awnumar]

Thanks for looking into this and providing a patch. I have merged your PR and added you to the authors file.

I can no longer reproduce the deadlock on my system. Your PoC does however produce some panics that are very interesting. I have added it to the examples submodule to investigate when I have more time.

Thanks again, and keep safe :)