Signal handlers call non-signal-safe functions

sth commented

2020-02-16 03:06:09 +01:00

(Migrated from github.com)

Describe the issue
The exit_handler tries to write log messages with y_log_message, which is not async signal safe. This can lead to a deadlock.

I got this stack trace:

Thread 3 (LWP 9796):
#0  __wait (addr=addr@entry=0x7f36ffd3dae8 <mal+104>, waiters=waiters@entry=0x7f36ffd3daec <mal+108>, val=val@entry=1, priv=128, priv@entry=1) at ./arch/x86_64/syscall_arch.h:40
#1  0x00007f36ffccf3ce in lock (lk=0x7f36ffd3dae8 <mal+104>) at src/malloc/malloc.c:30
#2  lock_bin (i=4) at src/malloc/malloc.c:43
#3  malloc (n=<optimized out>) at src/malloc/malloc.c:317
#4  0x00007f36ffabe009 in o_malloc () from /usr/lib/liborcania.so.2.1
#5  0x00007f36ffab7b6a in y_log_message () from /usr/lib/libyder.so.1.4
#6  0x00005638389be3f3 in exit_handler ()
#7  <signal handler called>
#8  0x00007f36ffcceb94 in unbin (c=c@entry=0x56383a6700d0, i=i@entry=4) at src/malloc/malloc.c:192
#9  0x00007f36ffccf472 in malloc (n=<optimized out>) at src/malloc/malloc.c:320
#10 0x00007f36ffca5388 in json_array () from /usr/lib/libjansson.so.4
#11 0x00007f36ffa8db00 in h_execute_query_json_sqlite () from /usr/lib/libhoel.so.1.4
#12 0x00007f36ffa8e13a in h_execute_query_json () from /usr/lib/libhoel.so.1.4
#13 0x00007f36ffa8eb26 in h_query_select_json () from /usr/lib/libhoel.so.1.4
#14 0x00007f36ffa8a7ca in h_select () from /usr/lib/libhoel.so.1.4
#15 0x000056383899f87b in get_client_module_list ()
#16 0x0000563838999012 in get_client ()
#17 0x00005638389a385b in glewlwyd_callback_check_client_valid ()
#18 0x00007f36ff030755 in check_auth_type_client_credentials_grant () from /usr/lib/glewlwyd/plugin/libprotocol_oauth2.so
#19 0x00007f36ff031edd in callback_oauth2_token ()  (please complete the following information)from /usr/lib/glewlwyd/plugin/libprotocol_oauth2.so
#20 0x00007f36ffaa8fd0 in ulfius_webservice_dispatcher () from /usr/lib/libulfius.so.2.6
#21 0x00007f36ff730c23 in ?? () from /usr/lib/libmicrohttpd.so.12
#22 0x00007f36ff732a97 in ?? () from /usr/lib/libmicrohttpd.so.12
#23 0x00007f36ff733b25 in ?? () from /usr/lib/libmicrohttpd.so.12
#24 0x00007f36ff736a12 in ?? () from /usr/lib/libmicrohttpd.so.12
#25 0x00007f36ffcfd33e in start (p=0x7f36fefcd8c0) at src/thread/pthread_create.c:192
#26 0x00007f36ffcff447 in __clone () at src/thread/x86_64/clone.s:22
Backtrace stopped: frame did not save the PC

As can be seen, the thread is busy inside malloc() in frame 9. It likely has a lock on some internal malloc structure. In this state a signal arrives and the thread jumps to a signal handler (frame 7). This handler (indirectly) calls malloc() again (frame 3) which tries to obtain a lock. Most likely this is the same lock that is already held in frame 9, causing a deadlock.

Expected behavior
A deadlock is annoying because it is not clear from the outside that the program stopped working, so that should be avoided. For non-fatal signals like SIGINT the main function could print the message after it got woken up by the condition variable, but for signals like SIGSEGV that's not an option, so I don't see how a message could be logged there without running into these kind of problems.

Plain write() is async signal safe, which could be used to write a message to stderr, but I'm not sure if doing that is worth it.

System:
Latest babelouest/glewlwyd docker.

**Describe the issue** The `exit_handler` tries to write log messages with `y_log_message`, which is not async signal safe. This can lead to a deadlock. I got this stack trace: ``` Thread 3 (LWP 9796): #0 __wait (addr=addr@entry=0x7f36ffd3dae8 <mal+104>, waiters=waiters@entry=0x7f36ffd3daec <mal+108>, val=val@entry=1, priv=128, priv@entry=1) at ./arch/x86_64/syscall_arch.h:40 #1 0x00007f36ffccf3ce in lock (lk=0x7f36ffd3dae8 <mal+104>) at src/malloc/malloc.c:30 #2 lock_bin (i=4) at src/malloc/malloc.c:43 #3 malloc (n=<optimized out>) at src/malloc/malloc.c:317 #4 0x00007f36ffabe009 in o_malloc () from /usr/lib/liborcania.so.2.1 #5 0x00007f36ffab7b6a in y_log_message () from /usr/lib/libyder.so.1.4 #6 0x00005638389be3f3 in exit_handler () #7 <signal handler called> #8 0x00007f36ffcceb94 in unbin (c=c@entry=0x56383a6700d0, i=i@entry=4) at src/malloc/malloc.c:192 #9 0x00007f36ffccf472 in malloc (n=<optimized out>) at src/malloc/malloc.c:320 #10 0x00007f36ffca5388 in json_array () from /usr/lib/libjansson.so.4 #11 0x00007f36ffa8db00 in h_execute_query_json_sqlite () from /usr/lib/libhoel.so.1.4 #12 0x00007f36ffa8e13a in h_execute_query_json () from /usr/lib/libhoel.so.1.4 #13 0x00007f36ffa8eb26 in h_query_select_json () from /usr/lib/libhoel.so.1.4 #14 0x00007f36ffa8a7ca in h_select () from /usr/lib/libhoel.so.1.4 #15 0x000056383899f87b in get_client_module_list () #16 0x0000563838999012 in get_client () #17 0x00005638389a385b in glewlwyd_callback_check_client_valid () #18 0x00007f36ff030755 in check_auth_type_client_credentials_grant () from /usr/lib/glewlwyd/plugin/libprotocol_oauth2.so #19 0x00007f36ff031edd in callback_oauth2_token () (please complete the following information)from /usr/lib/glewlwyd/plugin/libprotocol_oauth2.so #20 0x00007f36ffaa8fd0 in ulfius_webservice_dispatcher () from /usr/lib/libulfius.so.2.6 #21 0x00007f36ff730c23 in ?? () from /usr/lib/libmicrohttpd.so.12 #22 0x00007f36ff732a97 in ?? () from /usr/lib/libmicrohttpd.so.12 #23 0x00007f36ff733b25 in ?? () from /usr/lib/libmicrohttpd.so.12 #24 0x00007f36ff736a12 in ?? () from /usr/lib/libmicrohttpd.so.12 #25 0x00007f36ffcfd33e in start (p=0x7f36fefcd8c0) at src/thread/pthread_create.c:192 #26 0x00007f36ffcff447 in __clone () at src/thread/x86_64/clone.s:22 Backtrace stopped: frame did not save the PC ``` As can be seen, the thread is busy inside `malloc()` in frame 9. It likely has a lock on some internal malloc structure. In this state a signal arrives and the thread jumps to a signal handler (frame 7). This handler (indirectly) calls `malloc()` again (frame 3) which tries to obtain a lock. Most likely this is the same lock that is already held in frame 9, causing a deadlock. **Expected behavior** A deadlock is annoying because it is not clear from the outside that the program stopped working, so that should be avoided. For non-fatal signals like SIGINT the main function could print the message after it got woken up by the condition variable, but for signals like SIGSEGV that's not an option, so I don't see how a message could be logged there without running into these kind of problems. Plain `write()` is async signal safe, which could be used to write a message to stderr, but I'm not sure if doing that is worth it. **System:** Latest `babelouest/glewlwyd` docker.

babelouest commented

2020-02-16 16:16:09 +01:00

(Migrated from github.com)

Thanks for reporting,

I've never experienced deadlocks in Glewlwyd before, but I don't use docker images to run it so that may be because of Alpine Linux's different implementation.

I've created an issue in yder to discuss yder's side: babelouest/yder#16 , so you can add your feedback on it.

Concerning this issue, if I use less o_malloc in yder and more mutexes, this could ba a start, don't you think?

Thanks for reporting, I've never experienced deadlocks in Glewlwyd before, but I don't use docker images to run it so that may be because of Alpine Linux's different implementation. I've created an issue in yder to discuss yder's side: babelouest/yder#16 , so you can add your feedback on it. Concerning this issue, if I use less `o_malloc` in yder and more mutexes, this could ba a start, don't you think?

sth commented

2020-02-16 17:26:36 +01:00

(Migrated from github.com)

The root cause here was corruption of the internal malloc structures, I assume from a double free() caused by #104. This corruption resulted in a segfault in a later malloc call, leading to the above situation.

What exactly happens depends on the implementation of malloc. Alpine uses musl libc instead of the more common glibc, so it has a different malloc() implementation an behaves differently on such problems.

Generally I don't think more mutexes will help (rather the opposite). The main problem causing the deadlock is if a thread holds a lock, then gets interrupted by a signal, and then tries to aquire the same lock again in the signal handler. On the other hand if there is a static buffer not protected by a mutex that gets written to multiple times that will also not work out well...

Sadly I'm not an expert for signal handling, but maybe a strategy would be to have a dedicated thread to do signal handling, while signal handling is blocked for the other threads that do the real work. The signal handling thread would not do any malloc/locking/... and therefore if a signal arrives that thread would never get interrupted inside a lock. The signal handler would then be free to use the normal logging functions without danger.

There would still be some complications. Some signals might be delivered to specific threads, like SIGSEGV, and maybe always have their handler called on that thread (see some discussion here). That would need further investigation, I'm not sure about the details. Also for SIGSEGV and similar things you can never be sure calling a logging function will actually work. In the SIGSEGV case you most likely have some memory corruption somewhere and basically whatever you do might just run into another segmentation fault.

The root cause here was corruption of the internal malloc structures, I assume from a double free() caused by #104. This corruption resulted in a segfault in a later malloc call, leading to the above situation. What exactly happens depends on the implementation of malloc. Alpine uses musl libc instead of the more common glibc, so it has a different malloc() implementation an behaves differently on such problems. Generally I don't think more mutexes will help (rather the opposite). The main problem causing the deadlock is if a thread holds a lock, then gets interrupted by a signal, and then tries to aquire the same lock again in the signal handler. On the other hand if there is a static buffer not protected by a mutex that gets written to multiple times that will also not work out well... Sadly I'm not an expert for signal handling, but maybe a strategy would be to have a dedicated thread to do signal handling, while signal handling is blocked for the other threads that do the real work. The signal handling thread would not do any malloc/locking/... and therefore if a signal arrives that thread would never get interrupted inside a lock. The signal handler would then be free to use the normal logging functions without danger. There would still be some complications. Some signals might be delivered to specific threads, like SIGSEGV, and maybe always have their handler called on that thread (see some discussion [here][1]). That would need further investigation, I'm not sure about the details. Also for SIGSEGV and similar things you can never be sure calling a logging function will actually work. In the SIGSEGV case you most likely have some memory corruption somewhere and basically whatever you do might just run into another segmentation fault. [1]: https://stackoverflow.com/a/11679770/

babelouest commented

2020-02-16 19:02:47 +01:00

(Migrated from github.com)

Generally I don't think more mutexes will help (rather the opposite). [...] On the other hand if there is a static buffer not protected by a mutex that gets written to multiple times that will also not work out well...

Indeed, if I add a static buffer, I need to add a mutex, otherwise hell will be unleashed upon multi-threaded applications...

a strategy would be to have a dedicated thread to do signal handling, while signal handling is blocked for the other threads that do the real work

Could you provide a pull request for that? Also, would it be wise to do it, if the original problem was solved using getaddrinfo()?

> Generally I don't think more mutexes will help (rather the opposite). [...] On the other hand if there is a static buffer not protected by a mutex that gets written to multiple times that will also not work out well... Indeed, if I add a static buffer, I need to add a mutex, otherwise hell will be unleashed upon multi-threaded applications... > a strategy would be to have a dedicated thread to do signal handling, while signal handling is blocked for the other threads that do the real work Could you provide a pull request for that? Also, would it be wise to do it, if the original problem was solved using `getaddrinfo()`?

sth commented

2020-02-16 20:47:09 +01:00

(Migrated from github.com)

I'll have a look and see if I come up with something useful.

babelouest commented

2020-02-16 22:39:49 +01:00

(Migrated from github.com)

@sth , HYI, I reverted yder's last changes that were added to make it thread-safe, because as far as I can see, there's no visible difference in the performance or the safeness.

On the other hand, I made tests using yder/gethostbyname and yder/getaddrinfo in a multi-thread environment on a Linux Alpine docker instance.

The result shows that the new code doesn't change if the test program is more safe or not. The only visible change is when you switch to getaddrinfo, then the test program doesn't fails.

I came to the conclusion that adding static buffers and mutexes in yder is at least not useful, at worst could lead to new kind of problems. Therefore I reverted the changes.

Here is the surce program I used for my tests

#include <stdlib.h>
#include <stdio.h>
#include <unistd.h>
#include <pthread.h>
#include <netdb.h>

#include <yder.h>

#define THREADS_SIZE 128
#define LOOP_SIZE 50
#define HOST_LEN 128

#if 0
static void * log_flooder(void * args) {
  size_t i;
  char host[HOST_LEN+1] = {0};
  struct hostent * lh;
  
  for (i=0; i<LOOP_SIZE; i++) {
    snprintf(host, HOST_LEN, "%d.%d.%d.%d", rand()%256, rand()%256, rand()%256, rand()%256);
    lh = gethostbyname(host);
    if (lh) {
      y_log_message(Y_LOG_LEVEL_DEBUG, "%s resolved: '%s'", host, lh->h_name);
    } else {
      y_log_message(Y_LOG_LEVEL_DEBUG, "%s unresolved", host);
    }
    y_log_message(Y_LOG_LEVEL_DEBUG, "log message number %zu for thread %zu", i, (size_t)args);
    usleep(rand()%50);
  }
}
#else
static void * log_flooder(void * args) {
  size_t i;
  char host[HOST_LEN+1] = {0};
  struct addrinfo hints = { .ai_family = AF_UNSPEC, .ai_flags = AI_CANONNAME };
  struct addrinfo *lookup;
  
  for (i=0; i<LOOP_SIZE; i++) {
    snprintf(host, HOST_LEN, "%d.%d.%d.%d", rand()%256, rand()%256, rand()%256, rand()%256);
    if (!getaddrinfo(host, NULL, &hints, &lookup)) {
      if (lookup->ai_canonname) {
        y_log_message(Y_LOG_LEVEL_DEBUG, "%s resolved: '%s'", host, lookup->ai_canonname);
      } else {
        y_log_message(Y_LOG_LEVEL_DEBUG, "%s unresolved", host);
      }
    } else {
      y_log_message(Y_LOG_LEVEL_DEBUG, "getaddrinfo error, %s unresolved", host);
    }
    y_log_message(Y_LOG_LEVEL_DEBUG, "log message number %zu for thread %zu", i, (size_t)args);
    usleep(rand()%50);
  }
}
#endif

int main(void) {
  pthread_t threads[THREADS_SIZE];
  size_t i;
  
  srand(time(NULL));
  y_init_logs("yder-multithread", Y_LOG_MODE_FILE, Y_LOG_LEVEL_DEBUG, "/tmp/yder-multithread.log", "Start yder-multithread");
  
  for (i=0; i<THREADS_SIZE; i++) {
    pthread_create(&threads[i], NULL, log_flooder, (void *)i);
  }
  for (i=0; i<THREADS_SIZE; i++) {
    pthread_join(threads[i], NULL);
  }
  
  y_close_logs();
}

@sth , HYI, I [reverted](https://github.com/babelouest/yder/commit/42f8f60660bc07cf4ff50e2c8c6ac15cb16c3c53) yder's last changes that were added to make it thread-safe, because as far as I can see, there's no visible difference in the performance or the safeness. On the other hand, I made tests using `yder`/`gethostbyname` and `yder`/`getaddrinfo` in a multi-thread environment on a Linux Alpine docker instance. The result shows that the new code doesn't change if the test program is more safe or not. The only visible change is when you switch to `getaddrinfo`, then the test program doesn't fails. I came to the conclusion that adding static buffers and mutexes in yder is at least not useful, at worst could lead to new kind of problems. Therefore I reverted the changes. Here is the surce program I used for my tests ```C #include <stdlib.h> #include <stdio.h> #include <unistd.h> #include <pthread.h> #include <netdb.h> #include <yder.h> #define THREADS_SIZE 128 #define LOOP_SIZE 50 #define HOST_LEN 128 #if 0 static void * log_flooder(void * args) { size_t i; char host[HOST_LEN+1] = {0}; struct hostent * lh; for (i=0; i<LOOP_SIZE; i++) { snprintf(host, HOST_LEN, "%d.%d.%d.%d", rand()%256, rand()%256, rand()%256, rand()%256); lh = gethostbyname(host); if (lh) { y_log_message(Y_LOG_LEVEL_DEBUG, "%s resolved: '%s'", host, lh->h_name); } else { y_log_message(Y_LOG_LEVEL_DEBUG, "%s unresolved", host); } y_log_message(Y_LOG_LEVEL_DEBUG, "log message number %zu for thread %zu", i, (size_t)args); usleep(rand()%50); } } #else static void * log_flooder(void * args) { size_t i; char host[HOST_LEN+1] = {0}; struct addrinfo hints = { .ai_family = AF_UNSPEC, .ai_flags = AI_CANONNAME }; struct addrinfo *lookup; for (i=0; i<LOOP_SIZE; i++) { snprintf(host, HOST_LEN, "%d.%d.%d.%d", rand()%256, rand()%256, rand()%256, rand()%256); if (!getaddrinfo(host, NULL, &hints, &lookup)) { if (lookup->ai_canonname) { y_log_message(Y_LOG_LEVEL_DEBUG, "%s resolved: '%s'", host, lookup->ai_canonname); } else { y_log_message(Y_LOG_LEVEL_DEBUG, "%s unresolved", host); } } else { y_log_message(Y_LOG_LEVEL_DEBUG, "getaddrinfo error, %s unresolved", host); } y_log_message(Y_LOG_LEVEL_DEBUG, "log message number %zu for thread %zu", i, (size_t)args); usleep(rand()%50); } } #endif int main(void) { pthread_t threads[THREADS_SIZE]; size_t i; srand(time(NULL)); y_init_logs("yder-multithread", Y_LOG_MODE_FILE, Y_LOG_LEVEL_DEBUG, "/tmp/yder-multithread.log", "Start yder-multithread"); for (i=0; i<THREADS_SIZE; i++) { pthread_create(&threads[i], NULL, log_flooder, (void *)i); } for (i=0; i<THREADS_SIZE; i++) { pthread_join(threads[i], NULL); } y_close_logs(); } ```

babelouest commented

2020-02-21 03:40:17 +01:00

(Migrated from github.com)

Should be fixed now that #105 is merged, thanks @sth !

Rows
Columns

Signal handlers call non-signal-safe functions #103