From: Arran Cudbard-Bell Date: Fri, 27 Aug 2021 23:01:59 +0000 (-0500) Subject: Deal with race between EVFILT_READ and EVFILT_PROC X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=f00e7040da76714f2c6f7839b4425a06a3467c64;p=thirdparty%2Ffreeradius-server.git Deal with race between EVFILT_READ and EVFILT_PROC If EVFILT_PROC is delivered first we may never end up reading pending stdout/stderr data. --- diff --git a/src/lib/server/exec.c b/src/lib/server/exec.c index 277cfe30a1c..9f7d683d6e4 100644 --- a/src/lib/server/exec.c +++ b/src/lib/server/exec.c @@ -822,6 +822,7 @@ int fr_exec_wait_start(pid_t *pid_p, int *stdin_fd, int *stdout_fd, int *stderr_ talloc_free(argv); goto error; } + if (fr_nonblock(stdin_pipe[1]) < 0) PERROR("Error setting stdin to nonblock"); } if (stdout_fd) { @@ -831,6 +832,7 @@ int fr_exec_wait_start(pid_t *pid_p, int *stdin_fd, int *stdout_fd, int *stderr_ close(stdin_pipe[1]); goto error2; } + if (fr_nonblock(stdout_pipe[0]) < 0) PERROR("Error setting stdout to nonblock"); } if (stderr_fd) { @@ -839,6 +841,7 @@ int fr_exec_wait_start(pid_t *pid_p, int *stdin_fd, int *stdout_fd, int *stderr_ close(stdout_pipe[1]); goto error3; } + if (fr_nonblock(stderr_pipe[0]) < 0) PERROR("Error setting stderr to nonblock"); } pid = fork(); @@ -878,13 +881,11 @@ int fr_exec_wait_start(pid_t *pid_p, int *stdin_fd, int *stdout_fd, int *stderr_ if (stdout_fd) { *stdout_fd = stdout_pipe[0]; - fr_nonblock(*stdout_fd); close(stdout_pipe[1]); } if (stderr_fd) { *stderr_fd = stderr_pipe[0]; - fr_nonblock(*stderr_fd); close(stderr_pipe[1]); } @@ -899,6 +900,10 @@ static void exec_cleanup(fr_exec_state_t *exec) { if (exec->pid) DEBUG3("Cleaning up exec state for pid %u", exec->pid); + /* + * FIXME - Need to do something with stdin? + */ + if (exec->stdout_fd >= 0) { if (fr_event_fd_delete(request->el, exec->stdout_fd, FR_EVENT_FILTER_IO) < 0){ RPERROR("Failed removing stdout handler"); @@ -926,10 +931,41 @@ static void exec_cleanup(fr_exec_state_t *exec) { /* * Callback when exec has completed. Record the status and tidy up. */ -static void exec_waitpid(UNUSED fr_event_list_t *el, UNUSED pid_t pid, int status, void *uctx) +static void exec_waitpid(fr_event_list_t *el, UNUSED pid_t pid, int status, void *uctx) { - fr_exec_state_t *exec = uctx; + fr_exec_state_t *exec = uctx; /* may not be talloced */ request_t *request = exec->request; + int wait_status; + int ret; + + /* + * Reap the process. This is needed so the processes + * don't stick around indefinitely. libkqueue/kqueue + * does not do this for us! + * + * We do _not_ pass WNOHANG, if we hang here something + * is very wrong as we were notified that the process + * was done. + */ + ret = waitpid(exec->pid, &wait_status, WNOHANG); + if (ret < 0) { + RWDEBUG("Failed reaping PID %i: %s", exec->pid, fr_syserror(errno)); + /* + * Either something cleaned up the process before us + * (bad!), or the notification system is broke + * (also bad!) + * + * This could be caused by 3rd party libraries. + */ + } else if (ret == 0) { + RWDEBUG("Something reaped PID %d before us!", exec->pid); + /* + * This could be an implementation specific issue + * so don't assert. + */ + } else if (wait_status != status) { + RWDEBUG("Exit status from waitpid (%d) and kevent (%d) disagree", wait_status, status); + } if (WIFEXITED(status)) { RDEBUG("Program exited with status code %d", WEXITSTATUS(status)); @@ -946,50 +982,81 @@ static void exec_waitpid(UNUSED fr_event_list_t *el, UNUSED pid_t pid, int statu if (exec->ev) fr_event_timer_delete(&exec->ev); /* - * We may receive the "child exited" signal before the - * "pipe has been closed" signal + * Process exit notifications (EV_PROC) and file + * descriptor read events (EV_READ) can race. + * + * So... If the process has exited, trigger the IO + * handlers manually. + * + * This is icky, but the only other option is to + * enhance our event loop so we can look for + * pending events associated with file + * descriptors... + * + * Even then we might get the file readable + * notification and the process exited notification + * in different kevent() calls on busy systems. */ if (exec->stdout_fd >= 0) { - if (exec->stdout_used) { - RDEBUG("Program exited without EOF being read"); - return; - } - (void) fr_event_fd_delete(exec->request->el, exec->stdout_fd, FR_EVENT_FILTER_IO); + fr_event_fd_t *ef; + fr_event_fd_cb_t cb; + + ef = fr_event_fd_handle(el, exec->stdout_fd, FR_EVENT_FILTER_IO); + if (!fr_cond_assert_msg(ef, "no event associated with processes's stdout fd (%i)", + exec->stdout_fd)) goto close_stdout; + + cb = fr_event_fd_cb(ef, EVFILT_READ, 0); + if (!fr_cond_assert_msg(cb, "no read callback associated with processes's stdout_fd (%i)", + exec->stdout_fd)) goto close_stdout; + + /* + * Call the original read callback that + * was setup here to ensure that there's + * no pending data. + */ + cb(el, exec->stdout_fd, 0, fr_event_fd_uctx(ef)); + + /* + * ...and delete the event from the event + * loop. This should also suppress the + * EVFILT_READ event if there was one. + */ + (void) fr_event_fd_delete(el, exec->stdout_fd, FR_EVENT_FILTER_IO); + close_stdout: close(exec->stdout_fd); exec->stdout_fd = -1; } + if (exec->stderr_fd >= 0) { + fr_event_fd_t *ef; + fr_event_fd_cb_t cb; + + ef = fr_event_fd_handle(el, exec->stderr_fd, FR_EVENT_FILTER_IO); + if (!fr_cond_assert_msg(ef, "no event associated with processes's stderr fd (%i)", + exec->stderr_fd)) goto close_stderr; + + cb = fr_event_fd_cb(ef, EVFILT_READ, 0); + if (!fr_cond_assert_msg(cb, "no read callback associated with processes's stderr_fd (%i)", + exec->stderr_fd)) goto close_stderr; + + cb(el, exec->stderr_fd, 0, fr_event_fd_uctx(ef)); + (void) fr_event_fd_delete(el, exec->stderr_fd, FR_EVENT_FILTER_IO); + close_stderr: + close(exec->stderr_fd); + exec->stderr_fd = -1; + } + unlang_interpret_mark_runnable(exec->request); } /* * Callback when an exec times out. */ -static void exec_timeout( -#ifndef __linux__ - UNUSED -#endif - fr_event_list_t *el, UNUSED fr_time_t now, void *uctx) +static void exec_timeout(UNUSED fr_event_list_t *el, UNUSED fr_time_t now, void *uctx) { - fr_exec_state_t *exec = talloc_get_type_abort(uctx, fr_exec_state_t); + fr_exec_state_t *exec = uctx; /* may not be talloced */ request_t *request = exec->request; - fr_assert(exec->pid > 0); - -#ifdef __linux__ - int status; - - /* - * libkqueue on Linux isn't quite there yet. Maybe the - * program has exited, and we haven't noticed. In which - * case, do a graceful cleanup. - */ - if (waitpid(exec->pid, &status, WNOHANG) == exec->pid) { - exec_waitpid(el, exec->pid, status, exec); - return; - } -#endif - if (exec->stdout_fd < 0) { REDEBUG("Timeout waiting for program to exit - killing it and failing the request"); } else { @@ -1037,6 +1104,15 @@ static void exec_stdout_read(UNUSED fr_event_list_t *el, int fd, int flags, void if (data_len < 0) { if (errno == EINTR) continue; + /* + * This can happen when the callback is called + * manually when we're reaping the process. + * + * It's pretty much an identical condition to + * data_len == 0. + */ + if (errno == EWOULDBLOCK) break; + REDEBUG("Error reading from child program - %s", fr_syserror(errno)); goto error; } @@ -1082,26 +1158,40 @@ static void exec_stdout_read(UNUSED fr_event_list_t *el, int fd, int flags, void /** Call an child program, optionally reading it's output * - * @param[in] ctx to allocate events in. - * @param[in,out] exec structure holding the state of the external call. - * @param[in] request currently being processed. - * @param[in] cmd to call as a fr_value_boc_list_t. Program will be the first box - * and arguments in the subsequent boxes. - * @param[in] env_pairs list of pairs to be presented as evironment variables to the child. - * @param[in] timeout to wait for child to complete. + * @param[in] ctx to allocate events in. + * @param[in,out] exec structure holding the state of the external call. + * @param[in] request currently being processed. + * @param[in] cmd to call as a fr_value_boc_list_t. Program will be the first box + * and arguments in the subsequent boxes. + * @param[in] env_pairs list of pairs to be presented as evironment variables to the child. + * @param[in] need_stdin If true, allocate a pipe that will allow us to send data to the + * process. + * @param[in] store_stdout if true keep a copy of stdout in addition to logging + * it if RDEBUG_ENABLED2. + * @param[in] stdout_ctx ctx to alloc stdout data in. + * @param[in] timeout to wait for child to complete. * @return * - 0 on success * - -1 on failure */ -int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *request, fr_value_box_list_t *cmd, fr_pair_list_t *env_pairs, fr_time_delta_t timeout) +int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *request, + fr_value_box_list_t *cmd, fr_pair_list_t *env_pairs, + bool need_stdin, bool store_stdout, TALLOC_CTX *stdout_ctx, + fr_time_delta_t timeout) { - int *stdout_fd = (exec->stdout_used || RDEBUG_ENABLED2) ? &exec->stdout_fd : NULL; + int *stdout_fd = (store_stdout || RDEBUG_ENABLED2) ? &exec->stdout_fd : NULL; - exec->request = request; - exec->vps = env_pairs; - exec->stdout_fd = -1; - exec->stderr_fd = -1; - exec->stdin_fd = -1; + *exec = (fr_exec_state_t){ + .request = request, + .vps = env_pairs, + .stdout_fd = -1, + .stderr_fd = -1, + .stdin_fd = -1, + .status = -1, /* default to program didn't work */ + .stdin_used = need_stdin, + .stdout_used = store_stdout, + .stdout_ctx = stdout_ctx + }; if (fr_exec_wait_start(&exec->pid, exec->stdin_used ? &exec->stdin_fd : NULL, stdout_fd, &exec->stderr_fd, request, cmd, exec->vps) < 0) { @@ -1110,7 +1200,6 @@ int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *req exec_cleanup(exec); return -1; } - exec->status = -1; /* default to program didn't work */ /* * Tell the event loop that it needs to wait for this PID @@ -1124,9 +1213,7 @@ int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *req /* * Setup event to kill the child process after a period of time. */ - if (fr_event_timer_in(ctx, request->el, &exec->ev, timeout, exec_timeout, exec) < 0) { - goto fail; - } + if (fr_event_timer_in(ctx, request->el, &exec->ev, timeout, exec_timeout, exec) < 0) goto fail; /* * If we need to parse stdout, insert a special IO handler that @@ -1136,7 +1223,7 @@ int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *req /* * Accept a maximum of 32k of data from the process. */ - fr_sbuff_init_talloc(exec->outctx, &exec->stdout_buff, &exec->stdout_tctx, 128, 32 * 1024); + fr_sbuff_init_talloc(exec->stdout_ctx, &exec->stdout_buff, &exec->stdout_tctx, 128, 32 * 1024); if (fr_event_fd_insert(ctx, request->el, exec->stdout_fd, exec_stdout_read, NULL, NULL, exec) < 0) { RPEDEBUG("Failed adding event listening to stdout"); goto fail; @@ -1147,11 +1234,12 @@ int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *req * into the request log if we're logging at a high enough level of verbosity. */ } else if (RDEBUG_ENABLED2) { + snprintf(exec->stdout_prefix, sizeof(exec->stdout_prefix), "pid %u (stdout)", exec->pid); exec->stdout_uctx = (log_fd_event_ctx_t) { .type = L_DBG, .lvl = L_DBG_LVL_2, .request = request, - .prefix = fr_asprintf(exec->outctx, "pid %u (stdout)", exec->pid) + .prefix = exec->stdout_prefix }; if (fr_event_fd_insert(ctx, request->el, exec->stdout_fd, log_request_fd_event, @@ -1164,11 +1252,12 @@ int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *req /* * Send stderr to the request log as error messages with a custom prefix */ + snprintf(exec->stderr_prefix, sizeof(exec->stderr_prefix), "pid %u (stderr)", exec->pid); exec->stderr_uctx = (log_fd_event_ctx_t) { .type = L_DBG_ERR, .lvl = L_DBG_LVL_1, .request = request, - .prefix = fr_asprintf(exec->outctx, "pid %u (stderr)", exec->pid) + .prefix = exec->stderr_prefix }; if (fr_event_fd_insert(ctx, request->el, exec->stderr_fd, log_request_fd_event, diff --git a/src/lib/server/exec.h b/src/lib/server/exec.h index 9c913c82c1b..084e9887aa3 100644 --- a/src/lib/server/exec.h +++ b/src/lib/server/exec.h @@ -52,12 +52,17 @@ typedef struct { log_fd_event_ctx_t stdout_uctx; //!< Config for the stdout logger. log_fd_event_ctx_t stderr_uctx; //!< Config for the stderr logger. + char stdout_prefix[sizeof("pid -9223372036854775808 (stdout)")]; + char stderr_prefix[sizeof("pid -9223372036854775808 (stderr)")]; pid_t pid; //!< child PID int stdin_fd; //!< for writing to the child. bool stdin_used; //!< use stdin fd? int stdout_fd; //!< for reading from the child. + bool stdout_used; //!< use stdout fd? + TALLOC_CTX *stdout_ctx; //!< ctx to allocate output buffers + int stderr_fd; //!< for producing error messages. fr_event_timer_t const *ev; //!< for timing out the child @@ -70,7 +75,7 @@ typedef struct { fr_pair_list_t *vps; //!< input VPs request_t *request; //!< request this exec is related to - TALLOC_CTX *outctx; //!< ctx to allocate output buffers + } fr_exec_state_t; @@ -91,7 +96,9 @@ int fr_exec_wait_start(pid_t *pid_p, int *stdin_fd, int *stdout_fd, int *stderr_ request_t *request, fr_value_box_list_t *vb_list, fr_pair_list_t *env_pairs); int fr_exec_wait_start_io(TALLOC_CTX *ctx, fr_exec_state_t *exec, request_t *request, - fr_value_box_list_t *vb_list, fr_pair_list_t *env_pairs, fr_time_delta_t timeout); + fr_value_box_list_t *vb_list, fr_pair_list_t *env_pairs, + bool need_stdin, bool store_stdout, TALLOC_CTX *stdout_ctx, + fr_time_delta_t timeout); #ifdef __cplusplus } #endif diff --git a/src/lib/unlang/tmpl.c b/src/lib/unlang/tmpl.c index f06959ccc31..f909db1ea3a 100644 --- a/src/lib/unlang/tmpl.c +++ b/src/lib/unlang/tmpl.c @@ -275,13 +275,12 @@ static unlang_action_t unlang_tmpl_exec_wait_resume(rlm_rcode_t *p_result, reque { unlang_frame_state_tmpl_t *state = talloc_get_type_abort(frame->state, unlang_frame_state_tmpl_t); - state->exec.stdout_used = (state->out) ? true : false; - state->exec.outctx = state; - /* * @todo - make the timeout configurable */ - if (fr_exec_wait_start_io(state->ctx, &state->exec, request, &state->box, state->exec.vps, + if (fr_exec_wait_start_io(state->ctx, &state->exec, request, &state->box, + state->exec.vps, + false, (state->out != NULL), state, fr_time_delta_from_sec(EXEC_TIMEOUT)) < 0) { *p_result = RLM_MODULE_FAIL; return UNLANG_ACTION_CALCULATE_RESULT; diff --git a/src/modules/rlm_exec/rlm_exec.c b/src/modules/rlm_exec/rlm_exec.c index b63c09d2954..5aa454412e1 100644 --- a/src/modules/rlm_exec/rlm_exec.c +++ b/src/modules/rlm_exec/rlm_exec.c @@ -137,11 +137,11 @@ static xlat_action_t exec_xlat(TALLOC_CTX *ctx, UNUSED fr_dcursor_t *out, reques return XLAT_ACTION_DONE; } - exec = talloc_zero(request, fr_exec_state_t); - exec->stdout_used = inst->wait; - exec->outctx = ctx; + MEM(exec = talloc_zero(request, fr_exec_state_t)); /* Fixme - Should be frame ctx */ - if(fr_exec_wait_start_io(exec, exec, request, in, input_pairs, inst->timeout) < 0) { + if (fr_exec_wait_start_io(exec, exec, request, in, input_pairs, + false, inst->wait, ctx, + inst->timeout) < 0) { talloc_free(exec); return XLAT_ACTION_FAIL; }