From 6955a5c2a0abf38adace2553f21ea072416b1f61 Mon Sep 17 00:00:00 2001

From: =?UTF-8?q?Fabiano=20Fid=C3=AAncio?= <fidencio@redhat.com>

Date: Wed, 7 Dec 2016 21:36:56 +0100

Subject: [PATCH 160/160] WATCHDOG: Avoid non async-signal-safe from the

 signal_handler

MIME-Version: 1.0

Content-Type: text/plain; charset=UTF-8

Content-Transfer-Encoding: 8bit

While debugging rhbz#1396912 a deadlock on sssd_be was noticed[0] and

it's been caused by the use of non async-signal-safe functions from the

signal_handler (please, see man 7 signal for more info about which are

the async-signal-safe functions that can be used).

In order to work this situation around a pipe has been added to the

watchdog_ctx structure and, in case of clock screw,  a single byte is

written to this pipe (which is an async-signal-safe operation) and the

logic currently done by the timer handler to reset the watchdog will be

done inside the fd handler in a safe way.

With this patch we ended up losing some debug messages as

orderly_shutdown() has been replaced by kill(-getpgrp(), SIGTERM) (or

_exit(1) considering the cases where setting up the process group during

the server_setup() has failed).

Personally I don't think is worth the trouble to try to log those messages

properly in this specific case.

It's really worth to mention that a proper fix the clock screw situation

should be implemented on samba's side, by having tevent using monotonic

(or boottime) clock.

[0]:

  [root@dusan ~]# pstack 17922

    #0  __lll_lock_wait_private () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95

    #1  0x00007fe707d04f93 in _L_lock_14932 () from /lib64/libc.so.6

    #2  0x00007fe707d02013 in __GI___libc_malloc (bytes=140630248638304, bytes@entry=15) at malloc.c:2891

    #3  0x00007fe707d0888a in __GI___strdup (s=0x7fe707dff4f7 "/etc/localtime") at strdup.c:42

    #4  0x00007fe707d31b61 in tzset_internal (always=<optimized out>, explicit=explicit@entry=1) at tzset.c:438

    #5  0x00007fe707d32523 in __tz_convert (timer=timer@entry=0x7ffcd5d2b090, use_localtime=use_localtime@entry=1, tp=tp@entry=0x7fe708041d40 <_tmbuf>) at tzset.c:621

    #6  0x00007fe707d30521 in __GI_localtime (t=t@entry=0x7ffcd5d2b090) at localtime.c:42

    #7  0x00007fe70886c7b0 in sss_vdebug_fn (file=<optimized out>, line=<optimized out>, function=0x7fe70bff27f0 <__FUNCTION__.9379> "watchdog_handler", level=16, flags=flags@entry=0, format=format@entry=0x7fe70bff2760 "Watchdog timer overflow, killing process!\n", ap=ap@entry=0x7ffcd5d2b130) at src/util/debug.c:248

    #8  0x00007fe70886c995 in sss_debug_fn (file=file@entry=0x7fe70bff263b "src/util/util_watchdog.c", line=line@entry=82, function=function@entry=0x7fe70bff27f0 <__FUNCTION__.9379> "watchdog_handler", level=level@entry=16, format=format@entry=0x7fe70bff2760 "Watchdog timer overflow, killing process!\n") at src/util/debug.c:284

    #9  0x00007fe70bfdb409 in watchdog_handler (sig=<optimized out>) at src/util/util_watchdog.c:81

    #10 <signal handler called>

    #11 0x00007fe707cff664 in _int_malloc (av=av@entry=0x7fe70803c760 <main_arena>, bytes=bytes@entry=151) at malloc.c:3494

    #12 0x00007fe707d01fbc in __GI___libc_malloc (bytes=bytes@entry=151) at malloc.c:2893

    #13 0x00007fe708450749 in __talloc_with_prefix (prefix_len=0, size=55, context=0x7fe718373210) at ../talloc.c:668

    #14 __talloc (size=55, context=0x7fe718373210) at ../talloc.c:708

    #15 _talloc_named_const (name=0x7fe70bb7015d "../common/ldb_pack.c:425", size=55, context=0x7fe718373210) at ../talloc.c:865

    #16 talloc_named_const (context=<optimized out>, size=size@entry=55, name=name@entry=0x7fe70bb7015d "../common/ldb_pack.c:425") at ../talloc.c:1606

    #17 0x00007fe70bb61803 in ldb_unpack_data_only_attr_list (ldb=ldb@entry=0x7fe70e4d52c0, data=data@entry=0x7ffcd5d2b990, message=0x7fe7184aa1e0, list=list@entry=0x0, list_size=list_size@entry=0, nb_elements_in_db=nb_elements_in_db@entry=0x0) at ../common/ldb_pack.c:425

    #18 0x00007fe70bb61a7d in ldb_unpack_data (ldb=ldb@entry=0x7fe70e4d52c0, data=data@entry=0x7ffcd5d2b990, message=<optimized out>) at ../common/ldb_pack.c:470

    #19 0x00007fe6fdc29b46 in ltdb_parse_data_unpack (key=..., data=..., private_data=0x7ffcd5d2ba70) at ../ldb_tdb/ldb_search.c:249

    #20 0x00007fe70a5e0a24 in tdb_parse_data (tdb=tdb@entry=0x7fe70e4eaa10, key=..., offset=15619748, len=414772, parser=parser@entry=0x7fe6fdc29b10 <ltdb_parse_data_unpack>, private_data=private_data@entry=0x7ffcd5d2ba70) at ../common/io.c:637

    #21 0x00007fe70a5dc1fc in tdb_parse_record (tdb=0x7fe70e4eaa10, key=..., parser=parser@entry=0x7fe6fdc29b10 <ltdb_parse_data_unpack>, private_data=private_data@entry=0x7ffcd5d2ba70) at ../common/tdb.c:253

    #22 0x00007fe6fdc29e7b in ltdb_search_dn1 (module=module@entry=0x7fe70e4eab50, dn=dn@entry=0x7fe7183c4940, msg=msg@entry=0x7fe7184aa1e0) at ../ldb_tdb/ldb_search.c:287

    #23 0x00007fe6fdc2acbb in ltdb_dn_list_load (module=module@entry=0x7fe70e4eab50, dn=dn@entry=0x7fe7183c4940, list=list@entry=0x7fe7183c3a30) at ../ldb_tdb/ldb_index.c:181

    #24 0x00007fe6fdc2bbbb in ltdb_index_add1 (module=module@entry=0x7fe70e4eab50, dn=dn@entry=0x7fe7183bf3e0 "name=testuser7045@domain.com,cn=users,cn=DOMAIN.COM,cn=sysdb", v_idx=v_idx@entry=0, el=<optimized out>, el=<optimized out>) at ../ldb_tdb/ldb_index.c:1134

    #25 0x00007fe6fdc2c62c in ltdb_index_add_el (el=0x7fe7184aa3e0, dn=0x7fe7183bf3e0 "name=testuser7045@domain.com,cn=users,cn=DOMAIN.COM,cn=sysdb", module=0x7fe70e4eab50) at ../ldb_tdb/ldb_index.c:1180

    #26 ltdb_index_add_element (module=module@entry=0x7fe70e4eab50, dn=<optimized out>, el=el@entry=0x7fe7184aa3e0) at ../ldb_tdb/ldb_index.c:1290

    #27 0x00007fe6fdc290bb in ltdb_modify_internal (module=module@entry=0x7fe70e4eab50, msg=0x7fe7183bf0c0, req=req@entry=0x7fe7183bdc10) at ../ldb_tdb/ldb_tdb.c:903

    #28 0x00007fe6fdc2958a in ltdb_modify (ctx=0x7fe7183c2950, ctx=0x7fe7183c2950) at ../ldb_tdb/ldb_tdb.c:998

    #29 ltdb_callback (ev=<optimized out>, te=<optimized out>, t=..., private_data=<optimized out>) at ../ldb_tdb/ldb_tdb.c:1380

    #30 0x00007fe708664b4f in tevent_common_loop_timer_delay (ev=ev@entry=0x7fe70e4d2890) at ../tevent_timed.c:341

    #31 0x00007fe708665b5a in epoll_event_loop_once (ev=0x7fe70e4d2890, location=<optimized out>) at ../tevent_epoll.c:911

    #32 0x00007fe708664257 in std_event_loop_once (ev=0x7fe70e4d2890, location=0x7fe70bb72ec5 "../common/ldb.c:631") at ../tevent_standard.c:114

    #33 0x00007fe70866040d in _tevent_loop_once (ev=ev@entry=0x7fe70e4d2890, location=location@entry=0x7fe70bb72ec5 "../common/ldb.c:631") at ../tevent.c:533

    #34 0x00007fe70bb6bc4f in ldb_wait (handle=0x7fe7183c4530, type=<optimized out>) at ../common/ldb.c:631

    #35 0x00007fe70bb6c793 in ldb_autotransaction_request (ldb=0x7fe70e4d52c0, req=0x7fe7183bdc10) at ../common/ldb.c:573

    #36 0x00007fe70bb6d263 in ldb_modify (ldb=ldb@entry=0x7fe70e4d52c0, message=<optimized out>) at ../common/ldb.c:1655

    #37 0x00007fe70bfa2ab5 in sysdb_set_cache_entry_attr (ldb=0x7fe70e4d52c0, entry_dn=entry_dn@entry=0x7fe7183c4760, attrs=attrs@entry=0x7fe7183bf680, mod_op=mod_op@entry=2) at src/db/sysdb_ops.c:1159

    #38 0x00007fe70bfa304d in sysdb_rep_ts_entry_attr (sysdb=0x7fe70e4eadd0, attrs=0x7fe7183bf680, entry_dn=0x7fe7183c4760) at src/db/sysdb_ops.c:1218

    #39 sysdb_set_ts_entry_attr (sysdb=sysdb@entry=0x7fe70e4eadd0, entry_dn=entry_dn@entry=0x7fe7183c4760, attrs=attrs@entry=0x7fe7183bb840, mod_op=mod_op@entry=2) at src/db/sysdb_ops.c:1248

    #40 0x00007fe70bfa4aa9 in sysdb_set_entry_attr (sysdb=0x7fe70e4eadd0, entry_dn=0x7fe7183c4760, attrs=attrs@entry=0x7fe7183bb840, mod_op=mod_op@entry=2) at src/db/sysdb_ops.c:1199

    #41 0x00007fe70bfa4b5f in sysdb_set_user_attr (domain=domain@entry=0x7fe70e4d62f0, name=name@entry=0x7fe7183c01f0 "testuser7045@domain.com", attrs=attrs@entry=0x7fe7183bb840, mod_op=mod_op@entry=2) at src/db/sysdb_ops.c:1285

    #42 0x00007fe70bfa58c3 in sysdb_add_user (domain=domain@entry=0x7fe70e4d62f0, name=name@entry=0x7fe7183c01f0 "testuser7045@domain.com", uid=uid@entry=1415408147, gid=<optimized out>, gid@entry=1415400513, gecos=gecos@entry=0x7fe710465d00 "Test User7045", homedir=homedir@entry=0x0, shell=shell@entry=0x0, orig_dn=orig_dn@entry=0x7fe710465940 "CN=Test User7045,OU=Sales,DC=DOMAIN,DC=COM", attrs=attrs@entry=0x7fe7183bb840, cache_timeout=cache_timeout@entry=5400, now=now@entry=1481105315) at src/db/sysdb_ops.c:1928

    #43 0x00007fe70bfab271 in sysdb_store_new_user (now=1481105315, cache_timeout=5400, attrs=0x7fe7183bb840, orig_dn=0x7fe710465940 "CN=Test User7045,OU=Sales,DC=DOMAIN,DC=COM", shell=0x0, homedir=0x0, gecos=0x7fe710465d00 "Test User7045", gid=1415400513, uid=1415408147, name=0x7fe7183c01f0 "testuser7045@domain.com", domain=0x7fe70e4d62f0) at src/db/sysdb_ops.c:2549

    #44 sysdb_store_user (domain=domain@entry=0x7fe70e4d62f0, name=0x7fe7183c01f0 "testuser7045@domain.com", pwd=pwd@entry=0x0, uid=1415408147, gid=1415400513, gecos=gecos@entry=0x7fe710465d00 "Test User7045", homedir=homedir@entry=0x0, shell=shell@entry=0x0, orig_dn=orig_dn@entry=0x7fe710465940 "CN=Test User7045,OU=Sales,DC=DOMAIN,DC=COM", attrs=attrs@entry=0x7fe7183bb840, remove_attrs=0x7fe7183c08a0, cache_timeout=cache_timeout@entry=5400, now=now@entry=1481105315) at src/db/sysdb_ops.c:2499

    #45 0x00007fe6fba0d9f9 in sdap_save_user (memctx=memctx@entry=0x7fe70e544ee0, opts=opts@entry=0x7fe70e518400, dom=dom@entry=0x7fe70e4d62f0, attrs=<optimized out>, _usn_value=_usn_value@entry=0x7ffcd5d2c260, now=now@entry=1481105315) at src/providers/ldap/sdap_async_users.c:509

    #46 0x00007fe6fba0df9a in sdap_save_users (memctx=memctx@entry=0x7fe70e544e40, sysdb=0x7fe70e4eadd0, dom=0x7fe70e4d62f0, opts=0x7fe70e518400, users=<optimized out>, num_users=10006, _usn_value=_usn_value@entry=0x7fe70e544e60) at src/providers/ldap/sdap_async_users.c:572

    #47 0x00007fe6fba0e460 in sdap_get_users_done (subreq=<optimized out>) at src/providers/ldap/sdap_async_users.c:938

    #48 0x00007fe6fba0c9d5 in sdap_search_user_process (subreq=0x0) at src/providers/ldap/sdap_async_users.c:814

    #49 0x00007fe6fba07379 in generic_ext_search_handler (subreq=0x0, opts=<optimized out>) at src/providers/ldap/sdap_async.c:1689

    #50 0x00007fe6fba0991b in sdap_get_generic_op_finished (op=<optimized out>, reply=<optimized out>, error=<optimized out>, pvt=<optimized out>) at src/providers/ldap/sdap_async.c:1621

    #51 0x00007fe6fba083cd in sdap_process_message (ev=<optimized out>, sh=<optimized out>, msg=0x7fe70e5f9ce0) at src/providers/ldap/sdap_async.c:353

    #52 sdap_process_result (ev=<optimized out>, pvt=<optimized out>) at src/providers/ldap/sdap_async.c:197

    #53 0x00007fe708664b4f in tevent_common_loop_timer_delay (ev=ev@entry=0x7fe70e4cbc30) at ../tevent_timed.c:341

    #54 0x00007fe708665b5a in epoll_event_loop_once (ev=0x7fe70e4cbc30, location=<optimized out>) at ../tevent_epoll.c:911

    #55 0x00007fe708664257 in std_event_loop_once (ev=0x7fe70e4cbc30, location=0x7fe70bfee8e7 "src/util/server.c:702") at ../tevent_standard.c:114

    #56 0x00007fe70866040d in _tevent_loop_once (ev=ev@entry=0x7fe70e4cbc30, location=location@entry=0x7fe70bfee8e7 "src/util/server.c:702") at ../tevent.c:533

    #57 0x00007fe7086605ab in tevent_common_loop_wait (ev=0x7fe70e4cbc30, location=0x7fe70bfee8e7 "src/util/server.c:702") at ../tevent.c:637

    #58 0x00007fe7086641f7 in std_event_loop_wait (ev=0x7fe70e4cbc30, location=0x7fe70bfee8e7 "src/util/server.c:702") at ../tevent_standard.c:140

    #59 0x00007fe70bfd1993 in server_loop (main_ctx=0x7fe70e4cd080) at src/util/server.c:702

    #60 0x00007fe70c84cb82 in main (argc=8, argv=<optimized out>) at src/providers/data_provider_be.c:587

Resolves:

https://fedorahosted.org/sssd/ticket/3266

Signed-off-by: Fabiano Fidêncio <fidencio@redhat.com>

Reviewed-by: Pavel Březina <pbrezina@redhat.com>

Reviewed-by: Jakub Hrozek <jhrozek@redhat.com>

Reviewed-by: Simo Sorce <simo@redhat.com>

(cherry picked from commit e6a5f8c58539fc31fd81fac89cfc85703b4250ea)

(cherry picked from commit 0606a71b698c4acf954ba7284e62acbd0aa5e52d)

---

 src/util/util_watchdog.c | 118 ++++++++++++++++++++++++++++++++++++++---------

 1 file changed, 96 insertions(+), 22 deletions(-)

diff --git a/src/util/util_watchdog.c b/src/util/util_watchdog.c

index c184fbd759bdbca4a9eae379ff0d87e2d1628470..0df85b71c0b078dc2dfd23a39df82d1a10bad7d6 100644

--- a/src/util/util_watchdog.c

+++ b/src/util/util_watchdog.c

@@ -23,6 +23,7 @@

 #define WATCHDOG_DEF_INTERVAL 10

 #define WATCHDOG_MAX_TICKS 3

+#define DEFAULT_BUFFER_SIZE 4096

 /* this is intentionally a global variable */

 struct watchdog_ctx {

@@ -35,32 +36,27 @@ struct watchdog_ctx {

     struct tevent_context *ev;

     int input_interval;

     time_t timestamp;

+    struct tevent_fd *tfd;

+    int pipefd[2];

 } watchdog_ctx;

-static bool watchdog_detect_timeshift(void)

+static void watchdog_detect_timeshift(void)

 {

     time_t prev_time;

     time_t cur_time;

-    errno_t ret;

     prev_time = watchdog_ctx.timestamp;

     cur_time = watchdog_ctx.timestamp = time(NULL);

     if (cur_time < prev_time) {

         /* Time shift detected. We need to restart watchdog. */

-        DEBUG(SSSDBG_IMPORTANT_INFO, "Time shift detected, "

-              "restarting watchdog!\n");

-        teardown_watchdog();

-        ret = setup_watchdog(watchdog_ctx.ev, watchdog_ctx.input_interval);

-        if (ret != EOK) {

-            DEBUG(SSSDBG_FATAL_FAILURE, "Unable to restart watchdog "

-                  "[%d]: %s\n", ret, sss_strerror(ret));

-            orderly_shutdown(1);

+        if (write(watchdog_ctx.pipefd[1], "1", 1) != 1) {

+            if (getpid() == getpgrp()) {

+                kill(-getpgrp(), SIGTERM);

+            } else {

+                _exit(1);

+            }

         }

-

-        return true;

     }

-

-    return false;

 }

 /* the watchdog is purposefully *not* handled by the tevent

@@ -70,17 +66,16 @@ static bool watchdog_detect_timeshift(void)

  * signals either */

 static void watchdog_handler(int sig)

 {

-    /* Do not count ticks if time shift was detected

-     * since watchdog was restarted. */

-    if (watchdog_detect_timeshift()) {

-        return;

-    }

+

+    watchdog_detect_timeshift();

     /* if a pre-defined number of ticks passed by kills itself */

     if (__sync_add_and_fetch(&watchdog_ctx.ticks, 1) > WATCHDOG_MAX_TICKS) {

-        DEBUG(SSSDBG_FATAL_FAILURE,

-              "Watchdog timer overflow, killing process!\n");

-        orderly_shutdown(1);

+        if (getpid() == getpgrp()) {

+            kill(-getpgrp(), SIGTERM);

+        } else {

+            _exit(1);

+        }

     }

 }

@@ -109,10 +104,67 @@ static void watchdog_event_handler(struct tevent_context *ev,

     }

 }

+static errno_t watchdog_fd_recv_data(int fd)

+{

+    ssize_t len;

+    char buffer[DEFAULT_BUFFER_SIZE];

+    errno_t ret;

+

+    errno = 0;

+    len = read(fd, buffer, DEFAULT_BUFFER_SIZE);

+    if (len == -1) {

+        if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) {

+            return EAGAIN;

+        } else {

+            ret = errno;

+            DEBUG(SSSDBG_CRIT_FAILURE,

+                  "write failed [%d]: %s\n", ret, strerror(ret));

+            return ret;

+        }

+    }

+

+    return EOK;

+}

+

+static void watchdog_fd_read_handler(struct tevent_context *ev,

+                                     struct tevent_fd *fde,

+                                     uint16_t flags,

+                                     void *data)

+{

+    errno_t ret;

+

+    ret = watchdog_fd_recv_data(watchdog_ctx.pipefd[0]);

+    switch(ret) {

+    case EAGAIN:

+        DEBUG(SSSDBG_TRACE_ALL,

+              "Interrupted before any data could be read, retry later.\n");

+        return;

+    case EOK:

+        /* all fine */

+        break;

+    default:

+        DEBUG(SSSDBG_FATAL_FAILURE,

+              "Failed to receive data [%d]: %s. "

+              "orderly_shutdown() will be called.\n", ret, strerror(ret));

+        orderly_shutdown(1);

+    }

+

+    DEBUG(SSSDBG_IMPORTANT_INFO, "Time shift detected, "

+          "restarting watchdog!\n");

+    teardown_watchdog();

+    ret = setup_watchdog(watchdog_ctx.ev, watchdog_ctx.input_interval);

+    if (ret != EOK) {

+        DEBUG(SSSDBG_FATAL_FAILURE, "Unable to restart watchdog "

+              "[%d]: %s\n", ret, sss_strerror(ret));

+        orderly_shutdown(1);

+    }

+}

+

 int setup_watchdog(struct tevent_context *ev, int interval)

 {

     struct sigevent sev;

     struct itimerspec its;

+    struct tevent_fd *tfd;

     int signum = SIGRTMIN;

     int ret;

@@ -142,6 +194,21 @@ int setup_watchdog(struct tevent_context *ev, int interval)

     watchdog_ctx.input_interval = interval;

     watchdog_ctx.timestamp = time(NULL);

+    ret = pipe(watchdog_ctx.pipefd);

+    if (ret == -1) {

+        ret = errno;

+        DEBUG(SSSDBG_FATAL_FAILURE,

+              "pipe failed [%d] [%s].\n", ret, strerror(ret));

+        return ret;

+    }

+

+    sss_fd_nonblocking(watchdog_ctx.pipefd[0]);

+    sss_fd_nonblocking(watchdog_ctx.pipefd[1]);

+

+    tfd = tevent_add_fd(ev, (TALLOC_CTX *)ev, watchdog_ctx.pipefd[0],

+                        TEVENT_FD_READ, watchdog_fd_read_handler, NULL);

+    watchdog_ctx.tfd = tfd;

+

     /* Start the timer */

     /* we give 1 second head start to the watchdog event */

     its.it_value.tv_sec = interval + 1;

@@ -178,6 +245,13 @@ void teardown_watchdog(void)

              ret, strerror(ret));

     }

+    /* Free the tevent_fd */

+    talloc_zfree(watchdog_ctx.tfd);

+

+    /* Close the pipefds */

+    PIPE_FD_CLOSE(watchdog_ctx.pipefd[0]);

+    PIPE_FD_CLOSE(watchdog_ctx.pipefd[1]);

+

     /* and kill the watchdog event */

     talloc_free(watchdog_ctx.te);

 }

-- 

2.9.3