re_thread related questions

[juha-h]

When my baresip Android app calls ua_hangup, sometimes the call is made from re_thread and sometimes not. So there should be a way to check if the re_thread has already been entered.

There is function re_thread_check, but it does not only do the check, but also prints warning and possibly also backtrace:

	DEBUG_WARNING("thread check: called from a NON-RE thread without "
		      "thread_enter()!\n");

Could a new function be introduced that only returns the result without any log messages?

In re_thread_enter, why is re_lock called also when re_thread is not entered?

void re_thread_enter(void)
{
	struct re *re = re_get();

	if (!re) {
		DEBUG_WARNING("re_thread_enter: re not ready\n");
		return;
	}

	re_lock(re);

	/* set only for non-re threads */
	if (!thrd_equal(re->tid, thrd_current())) {
		re_atomic_rlx_set(&re->thread_enter, true);
	}
}

Or is the call harmless and does not cause any lockup?

[juha-h]

The first question was answered by commit 40a1b04.

Regarding the second question, I read some pthread docs and got impression that second call of re_lock does not cause a wait when mutex is recursive.

[juha-h]

I added debug to my ua_hangup function:

   const int thread_check = re_thread_check(false);
   LOGD("hanging up call %ld/%ld\n", (long)ua, (long)call);
    //if (thread_check != 0)
        re_thread_enter();
    LOGD( "returned from re_thread_enter\n");
    if (strlen(native_reason) == 0)
        ua_hangup((struct ua *)ua, (struct call *)call, native_code, NULL);
    else
        ua_hangup((struct ua *)ua, (struct call *)call, native_code, native_reason);
    //if (thread_check != 0)
        re_thread_leave();

When the thread check is commented out, second call of re_thread_enter never returns. When I hangup after first re_thread_enter call, I get to log:

04-29 13:20:53.266  4433  4433 D Baresip Lib: hanging up call -5476376615243027632/-5476376615243202032
04-29 13:20:53.266  4433  4433 D Baresip Lib: returned from re_thread_enter

But when I hangup while still on re thread, the second re_thread_enter call never returns:

04-29 13:21:21.167  4433  4433 D Baresip Lib: hanging up call -5476376615243027632/-5476376617356201968
// "returned from re_thread_enter" message never shows up.

In my opinion this is dangerous. re_thread_enter/leave should have some checks that automatically prevent this kind of lockups.

[juha-h]

I still don't understand how the re functions operate:

1. Why does re_enter call re_lock in case we already are on re thread and thus don't enter it?
2. In re_thread_check, how is it possible that re->dit equals thrd_current() when we have not entered re thread?

[sreimers]

A simplified example:

/* RE thread */
re_main(...)
{
	re_unlock();
	/* waiting for events (epoll_wait...) */
	re_lock();
        /* execute timers and async events (network etc.) */
}

With re_thread_enter you lock the re main thread after waiting for events to safely execute code that accesses socket or timer functions from application thread. To keep re_main running again you call re_thread_leave to unlock. This also works if multiple application threads try to call re_thread_enter() (only one thread can access safely socket/timer functions).

/*
 * This function can be called from the application's thread
 */
int application_ua_connect(void)
{
	int err;

	re_thread_enter();
	err = ua_connect()
	re_thread_leave();

	return err;
}

And if you have a callback handler registered that interacts with same application code (that possible calls re_thread_enter) you have to call re_thread_leave first (since re_main is locked while executing events/timers), otherwise next re_thread_enter locks forever.

/*
 * The callback handler is called from the RE thread.
 */
static void ua_event_handler(struct ua *ua, enum ua_event ev,
			  struct call *call, const char *prm, void *arg)
{
	re_thread_leave();
	call_ui_function();
	re_thread_enter();
}

A alternative solution is to use a thread safe message queue (mqueue):

https://github.com/baresip/baresip/wiki/Using-baresip-as-a-library#example-using-message-queue

[sreimers]

Can you try this PR: #782 it should help in some cases, to avoid a deadlock.

[juha-h]

Thanks for the suggestion. I installed the PR and here is my test code:

static void ua_event_handler(struct ua *ua, enum ua_event ev,
			     struct call *call, const char *prm, void *arg)
{
    (void)arg;
    LOGD("ua event (%s) %s re_thread %d\n", uag_event_str(ev), prm, re_thread_check(true));
    ...
    JNIEnv *env;
    jint res = (*g_ctx.javaVM)->GetEnv(g_ctx.javaVM, (void**)&env, JNI_VERSION_1_6);
    if (res != JNI_OK) {
        LOGE("failed to get environment: %d\n", res);
        return;
    }
    jmethodID methodId = (*env)->GetMethodID(env, g_ctx.mainActivityClz, "uaEvent", "(Ljava/lang/String;JJ)V");
    jstring jEvent = (*env)->NewStringUTF(env, event_buf);
    LOGD("sending ua/call %ld/%ld event %s\n", (long)ua, (long)call, event_buf);
    re_thread_leave();
    (*env)->CallVoidMethod(env, g_ctx.mainActivityObj, methodId, jEvent, (jlong)ua, (jlong)call);
    re_thread_enter();
    (*env)->DeleteLocalRef(env, jEvent);
}

And here is what I got to log:

05-03 09:35:11.418 31803 31852 D Baresip Lib: ua event (CREATE)  re_thread 0
05-03 09:35:11.418 31803 31852 D Baresip Lib: sending ua/call -5476376617179360944/0 event create
05-03 09:35:11.418 31803 31853 D Baresip Lib: main: re_unlock err
05-03 09:35:11.421 31803 31852 D Baresip : got uaEvent create/sip:bar@test.tutpro.com

My understanding is that the error comes from re_unlock call at the end of re_thread_leave function.

[juha-h]

Just in case it matters, I call re_thread_async_init(ASYNC_WORKERS) at baresip start:

    ...
    runLoggingThread();

    err = libre_init();
    if (err)
        goto out;

    if (re_thread_check(true) == 0) {
        LOGI("attaching to re thread\n");
        jint res = (*javaVM)->AttachCurrentThread(javaVM, &env, NULL);
        if (JNI_OK != res) {
            LOGE("failed to AttachCurrentThread: %d\n", res);
            goto out;
        }
    } else {
        LOGE("not on re thread\n");
        goto out;
    }

    conf_path_set(path);

    err = conf_configure();
    if (err) {
        LOGW("conf_configure() failed: (%d)\n", err);
        strcpy(start_error, "conf_configure");
        goto out;
    }

    re_thread_async_init(ASYNC_WORKERS);

    err = baresip_init(conf_config());
    if (err) {
        LOGW("baresip_init() failed (%d)\n", err);
        strcpy(start_error, "baresip_init");
        goto out;
    }
   ...

[juha-h]

Without the PR, there is no error message, but the app hangs. Therefore I'm currently not calling re_thread_leave/enter in ua_event_handler.

[sreimers]

a recursive pthread unlock returns error if you try to unlock and the current thread is not the owner of the lock.

PTHREAD_MUTEX_LOCK(3P):

If a thread attempts to unlock a mutex that it has not locked or a mutex which is unlocked, 
pthread_mutex_unlock() shall behave as described in the Unlock When Not Owner column of the  following table.

                                              ┌───────────┬────────────┬────────────────┬───────────────────────┐
                                              │Mutex Type │ Robustness │     Relock     │ Unlock When Not Owner │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │NORMAL     │ non-robust │ deadlock       │ undefined behavior    │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │NORMAL     │ robust     │ deadlock       │ error returned        │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │ERRORCHECK │ either     │ error returned │ error returned        │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │RECURSIVE  │ either     │ recursive      │ error returned        │
                                              │           │            │ (see below)    │                       │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │DEFAULT    │ non-robust │ undefined      │ undefined behavior†   │
                                              │           │            │ behavior†      │                       │
                                              ├───────────┼────────────┼────────────────┼───────────────────────┤
                                              │DEFAULT    │ robust     │ undefined      │ error returned        │
                                              │           │            │ behavior†      │                       │
                                              └───────────┴────────────┴────────────────┴───────────────────────┘

[juha-h]

I'm calling re_thread_leave in ua_event_handler which (as debug of #774 (comment) shows) is executed under re_thread. So how come the lock is not owned by re thread?

Could baresip start code #774 (comment) create the lock (e.g. in libre_init) when not in re thread?

[juha-h]

I add debug to baresip start code:

    LOGE("********** on re thread %d\n", re_thread_check(true));
    runLoggingThread();
    LOGE("********** on re thread %d\n", re_thread_check(true));
    err = libre_init();
    if (err)
        goto out;
    LOGE("********** on re thread %d\n", re_thread_check(true));

and the result is:

05-03 11:04:32.779  4210  4266 D Baresip Lib: ********** on re thread 22
05-03 11:04:32.780  4210  4266 D Baresip Lib: ********** on re thread 22
05-03 11:04:32.782  4210  4266 D Baresip Lib: ********** on re thread 0

So could the lock be created by runLoggingThread() or libre_init() before on re thread?

[juha-h]

static int runLoggingThread()
{
setvbuf(stdout, 0, _IOLBF, 0);
setvbuf(stderr, 0, _IONBF, 0);

pipe(pfd);
dup2(pfd[1], 1);
dup2(pfd[1], 2);

int ret = pthread_create(&loggingThread, NULL, loggingFunction, NULL);
if (ret != 0)
    return ret;

pthread_detach(loggingThread);

return 0;

}

[juha-h]

I added DEBUG_WARNING("re_lock called\n") to re_lock function. It shows that re_lock is not called by anyone before re_thread_leave call in ua_event_handler and when it is called there, the error occurs:

...
05-03 11:26:34.700  5141  5196 D Baresip Lib: module: loading app account.so
05-03 11:26:34.700  5141  5196 D Baresip Lib: bar@test.tutpro.com: Using sipnat: 'outbound'
05-03 11:26:34.700  5141  5195 D Baresip Lib: ua event (CREATE)  re_thread 0
05-03 11:26:34.701  5141  5196 D Baresip Lib: main: re_unlock err

So looks this is not correct example:

/*
 * The callback handler is called from the RE thread.
 */
static void ua_event_handler(struct ua *ua, enum ua_event ev,
			  struct call *call, const char *prm, void *arg)
{
	re_thread_leave();
	call_ui_function();
	re_thread_enter();
}```

[sreimers]

Right, on startup re_lock is not locked. The code example is for re_main() in running situation, you can simply check the event type. Looks like UA_EVENT_CREATE is a new case.

[juha-h]

ua_event_create can also occur in running situation when a new account is created on the fly. Using baresip as a library is a daunting task.

[sreimers]

Can you try: #784

[juha-h]

Thanks, PR #784 helped a lot. No more hang at baresip start. I'll do more testing after lunch break.

[juha-h]

I made more tests and #784 allowed me to remove all re_thread_check calls. No hangs anymore anywhere.