From fe2f4f3ec58ef03e8d3fe802283b848d54b5eb76 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 12:45:52 +0100 Subject: [PATCH 1/8] Remember to check for whether we actually did exit in tests. See: https://bugs.torproject.org/28179 --- src/test/test_process_slow.c | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/test_process_slow.c b/src/test/test_process_slow.c index a1f99bff0f..3f8c07f312 100644 --- a/src/test/test_process_slow.c +++ b/src/test/test_process_slow.c @@ -242,6 +242,7 @@ test_callbacks(void *arg) /* We returned. Let's see what our event loop said. */ tt_int_op(smartlist_len(process_data->stdout_data), OP_EQ, 12); tt_int_op(smartlist_len(process_data->stderr_data), OP_EQ, 3); + tt_assert(process_data->did_exit); tt_int_op(process_data->exit_code, OP_EQ, 0); /* Check stdout output. */ From 1d8dcb416c989ad86a1e3ae2aa92f4c2c1339183 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 12:47:04 +0100 Subject: [PATCH 2/8] Remember to close the child process' ends of the pipes. This prevents us from leaking the HANDLE for stdout, stderr, and stdin. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index c92b0975a7..a09664b501 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -248,6 +248,11 @@ process_win32_exec(process_t *process) win32_process->stderr_handle.pipe = stderr_pipe_read; win32_process->stdin_handle.pipe = stdin_pipe_write; + /* Close our ends of the pipes that is now owned by the child process. */ + CloseHandle(stdout_pipe_write); + CloseHandle(stderr_pipe_write); + CloseHandle(stdin_pipe_read); + /* Used by the callback functions from ReadFileEx() and WriteFileEx() such * that we can figure out which process_t that was responsible for the event. * From 44586a89ef636b0d3f736e44a1d2fc6497080bfc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 12:53:28 +0100 Subject: [PATCH 3/8] Delay checking process for termination until both stdout and stderr are closed. This patch makes us delay checking for whether we have an exit code value (via GetExitCodeProcess()) until both stdout and stderr have been closed by the operating system either by the process itself or by process cleanup after termination. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index a09664b501..52acf49370 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -525,6 +525,28 @@ process_win32_timer_test_process(process_t *process) BOOL ret = FALSE; DWORD exit_code = 0; + /* Sometimes the Windows kernel wont give us the EOF/Broken Pipe error + * message until some time after the process have actually terminated. We + * make sure that our ReadFileEx() calls for the process have *all* returned + * and both standard out and error have been marked as EOF before we try to + * see if the process terminated. + * + * This ensures that we *never* call the exit callback of the `process_t`, + * which potentially ends up calling `process_free()` on our `process_t`, + * before all data have been received from the process. + * + * We do NOT have a check here for whether standard in reached EOF since + * standard in's WriteFileEx() function is only called on-demand when we have + * something to write and is thus usually not awaiting to finish any + * operations. If we WriteFileEx() to a file that has terminated we'll simply + * get an error from ReadFileEx() or its completion routine and move on with + * life. */ + if (! win32_process->stdout_handle.reached_eof) + return false; + + if (! win32_process->stderr_handle.reached_eof) + return false; + /* We start by testing whether our process is still running. */ ret = GetExitCodeProcess(win32_process->process_information.hProcess, &exit_code); From c6e041e3d8dcc6f887014f9dd8887faebf5f4a49 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 12:57:20 +0100 Subject: [PATCH 4/8] Handle errors even after success from ReadFileEx() and WriteFileEx(). This patch adds some additional error checking after calls to ReadFileEx() and WriteFileEx(). I have not managed to get this code to reach the branch where `error_code` is NOT `ERROR_SUCCESS`, but MSDN says one should check for this condition so we do so just to be safe. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 50 +++++++++++++++++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index 52acf49370..71dd4001c8 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -329,6 +329,7 @@ process_win32_write(struct process_t *process, buf_t *buffer) process_win32_t *win32_process = process_get_win32_process(process); BOOL ret = FALSE; + DWORD error_code = 0; const size_t buffer_size = buf_datalen(buffer); /* Windows is still writing our buffer. */ @@ -350,6 +351,12 @@ process_win32_write(struct process_t *process, buf_t *buffer) /* Read data from the process_t buffer into our intermediate buffer. */ buf_get_bytes(buffer, win32_process->stdin_handle.buffer, write_size); + /* Because of the slightly weird API for WriteFileEx() we must set this to 0 + * before we call WriteFileEx() because WriteFileEx() does not reset the last + * error itself when it's succesful. See comment below after the call to + * GetLastError(). */ + SetLastError(0); + /* Schedule our write. */ ret = WriteFileEx(win32_process->stdin_handle.pipe, win32_process->stdin_handle.buffer, @@ -363,6 +370,24 @@ process_win32_write(struct process_t *process, buf_t *buffer) return 0; } + /* Here be dragons: According to MSDN's documentation for WriteFileEx() we + * should check GetLastError() after a call to WriteFileEx() even though the + * `ret` return value was successful. If everything is good, GetLastError() + * returns `ERROR_SUCCESS` and nothing happens. + * + * XXX(ahf): I have not managed to trigger this code while stress-testing + * this code. */ + error_code = GetLastError(); + + if (error_code != ERROR_SUCCESS) { + /* LCOV_EXCL_START */ + log_warn(LD_PROCESS, "WriteFileEx() failed after returning success: %s", + format_win32_error(error_code)); + win32_process->stdin_handle.reached_eof = true; + return 0; + /* LCOV_EXCL_STOP */ + } + /* This cast should be safe since our buffer can maximum be BUFFER_SIZE * large. */ return (int)write_size; @@ -864,6 +889,7 @@ process_win32_read_from_handle(process_win32_handle_t *handle, BOOL ret = FALSE; int bytes_available = 0; + DWORD error_code = 0; /* We already have a request to read data that isn't complete yet. */ if (BUG(handle->busy)) @@ -887,6 +913,12 @@ process_win32_read_from_handle(process_win32_handle_t *handle, memset(handle->buffer, 0, sizeof(handle->buffer)); } + /* Because of the slightly weird API for ReadFileEx() we must set this to 0 + * before we call ReadFileEx() because ReadFileEx() does not reset the last + * error itself when it's succesful. See comment below after the call to + * GetLastError(). */ + SetLastError(0); + /* Ask the Windows kernel to read data from our pipe into our buffer and call * the callback function when it is done. */ ret = ReadFileEx(handle->pipe, @@ -901,6 +933,24 @@ process_win32_read_from_handle(process_win32_handle_t *handle, return bytes_available; } + /* Here be dragons: According to MSDN's documentation for ReadFileEx() we + * should check GetLastError() after a call to ReadFileEx() even though the + * `ret` return value was successful. If everything is good, GetLastError() + * returns `ERROR_SUCCESS` and nothing happens. + * + * XXX(ahf): I have not managed to trigger this code while stress-testing + * this code. */ + error_code = GetLastError(); + + if (error_code != ERROR_SUCCESS) { + /* LCOV_EXCL_START */ + log_warn(LD_PROCESS, "ReadFileEx() failed after returning success: %s", + format_win32_error(error_code)); + handle->reached_eof = true; + return bytes_available; + /* LCOV_EXCL_STOP */ + } + /* We mark our handle as having a pending I/O request. */ handle->busy = true; From 36e24782f87c25d13b4c918c66cd4affaab8df79 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 13:02:22 +0100 Subject: [PATCH 5/8] Remember to set `reached_eof` when our handles are reporting errors. This patch adds some missing calls to set `reached_eof` of our handles when various error conditions happens or when we close our handle (which happens at `process_terminate()`. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index 71dd4001c8..358765f790 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -367,6 +367,7 @@ process_win32_write(struct process_t *process, buf_t *buffer) if (! ret) { log_warn(LD_PROCESS, "WriteFileEx() failed: %s", format_win32_error(GetLastError())); + win32_process->stdin_handle.reached_eof = true; return 0; } @@ -749,6 +750,7 @@ process_win32_cleanup_handle(process_win32_handle_t *handle) if (handle->pipe != INVALID_HANDLE_VALUE) { CloseHandle(handle->pipe); handle->pipe = INVALID_HANDLE_VALUE; + handle->reached_eof = true; } } @@ -930,6 +932,7 @@ process_win32_read_from_handle(process_win32_handle_t *handle, if (! ret) { log_warn(LD_PROCESS, "ReadFileEx() failed: %s", format_win32_error(GetLastError())); + handle->reached_eof = true; return bytes_available; } From f58e597d42c204e25101143f9618d55aef666edc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 13:04:49 +0100 Subject: [PATCH 6/8] Handle ERROR_BROKEN_PIPE in completion routines. Handle `ERROR_BROKEN_PIPE` from ReadFileEx() and WriteFileEx() in process_win32_stdin_write_done() and process_win32_handle_read_completion() instead of in the early handler. This most importantmly makes sure that `reached_eof` is set to true when these errors appears. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 37 ++++++--------------------------- 1 file changed, 6 insertions(+), 31 deletions(-) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index 358765f790..3b4373f425 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -765,15 +765,6 @@ process_win32_stdout_read_done(DWORD error_code, tor_assert(overlapped); tor_assert(overlapped->hEvent); - /* This happens when we have asked ReadFileEx() to read some data, but we - * then decided to call CloseHandle() on the HANDLE. This can happen if - * someone runs process_free() in the exit_callback of process_t, which means - * we cannot call process_get_win32_process() here. */ - if (error_code == ERROR_BROKEN_PIPE) { - log_debug(LD_PROCESS, "Process reported broken pipe on standard out"); - return; - } - /* Extract our process_t from the hEvent member of OVERLAPPED. */ process_t *process = (process_t *)overlapped->hEvent; process_win32_t *win32_process = process_get_win32_process(process); @@ -797,15 +788,6 @@ process_win32_stderr_read_done(DWORD error_code, tor_assert(overlapped); tor_assert(overlapped->hEvent); - /* This happens when we have asked ReadFileEx() to read some data, but we - * then decided to call CloseHandle() on the HANDLE. This can happen if - * someone runs process_free() in the exit_callback of process_t, which means - * we cannot call process_get_win32_process() here. */ - if (error_code == ERROR_BROKEN_PIPE) { - log_debug(LD_PROCESS, "Process reported broken pipe on standard error"); - return; - } - /* Extract our process_t from the hEvent member of OVERLAPPED. */ process_t *process = (process_t *)overlapped->hEvent; process_win32_t *win32_process = process_get_win32_process(process); @@ -831,15 +813,6 @@ process_win32_stdin_write_done(DWORD error_code, (void)byte_count; - /* This happens when we have asked WriteFileEx() to write some data, but we - * then decided to call CloseHandle() on the HANDLE. This can happen if - * someone runs process_free() in the exit_callback of process_t, which means - * we cannot call process_get_win32_process() here. */ - if (error_code == ERROR_BROKEN_PIPE) { - log_debug(LD_PROCESS, "Process reported broken pipe on standard input"); - return; - } - process_t *process = (process_t *)overlapped->hEvent; process_win32_t *win32_process = process_get_win32_process(process); @@ -860,7 +833,8 @@ process_win32_stdin_write_done(DWORD error_code, /* Schedule the next write. */ process_notify_event_stdin(process); - } else if (error_code == ERROR_HANDLE_EOF) { + } else if (error_code == ERROR_HANDLE_EOF || + error_code == ERROR_BROKEN_PIPE) { /* Our WriteFileEx() call was succesful, but we reached the end of our * file. We mark our handle as having reached EOF and returns. */ tor_assert(byte_count == 0); @@ -983,9 +957,10 @@ process_win32_handle_read_completion(process_win32_handle_t *handle, /* Tell our caller to schedule the next read. */ return true; - } else if (error_code == ERROR_HANDLE_EOF) { - /* Our ReadFileEx() call was succesful, but we reached the end of our file. - * We mark our handle as having reached EOF and returns. */ + } else if (error_code == ERROR_HANDLE_EOF || + error_code == ERROR_BROKEN_PIPE) { + /* Our ReadFileEx() finished, but we reached the end of our file. We mark + * our handle as having reached EOF and returns. */ tor_assert(byte_count == 0); handle->reached_eof = true; From 412fbe9f177f742e0e56df612f44261f6771973a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 13:11:24 +0100 Subject: [PATCH 7/8] Make example CancelIoEx() code use CancelIo(). This patch changes the CancelIoEx() example code to use CancelIo(), which is available for older versions of Windows too. I still think the kernel handles this nicely by sending broken pipes if either side closes the pipe while I/O operations are pending. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index 3b4373f425..641af2bb0f 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -720,30 +720,23 @@ process_win32_cleanup_handle(process_win32_handle_t *handle) tor_assert(handle); #if 0 - /* FIXME(ahf): My compiler does not set _WIN32_WINNT to a high enough value - * for this code to be available. Should we force it? CancelIoEx() is - * available from Windows 7 and above. If we decide to require this, we need - * to update the checks in all the three I/O completion callbacks to handle - * the ERROR_OPERATION_ABORTED as well as ERROR_BROKEN_PIPE. */ - -#if _WIN32_WINNT >= 0x0600 - /* This code is only supported from Windows 7 and onwards. */ BOOL ret; DWORD error_code; - /* Cancel any pending I/O requests. */ - ret = CancelIoEx(handle->pipe, &handle->overlapped); + /* Cancel any pending I/O requests: This means that instead of getting + * ERROR_BROKEN_PIPE we get ERROR_OPERATION_ABORTED, but it doesn't seem + * like this is needed. */ + ret = CancelIo(handle->pipe); if (! ret) { error_code = GetLastError(); /* There was no pending I/O requests for our handle. */ if (error_code != ERROR_NOT_FOUND) { - log_warn(LD_PROCESS, "CancelIoEx() failed: %s", + log_warn(LD_PROCESS, "CancelIo() failed: %s", format_win32_error(error_code)); } } -#endif #endif /* Close our handle. */ From 776208896756651519fd6540103c73a369b6d485 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20F=C3=A6r=C3=B8y?= Date: Thu, 20 Dec 2018 13:12:53 +0100 Subject: [PATCH 8/8] No need to log ordinary EOF conditions as LOG_WARN. Let's not use log_warn() when a pipe is closed under what should be considered normal conditions. See: https://bugs.torproject.org/28179 --- src/lib/process/process_win32.c | 26 ++++++++++++++++++++++---- 1 file changed, 22 insertions(+), 4 deletions(-) diff --git a/src/lib/process/process_win32.c b/src/lib/process/process_win32.c index 641af2bb0f..d8a895875c 100644 --- a/src/lib/process/process_win32.c +++ b/src/lib/process/process_win32.c @@ -365,8 +365,17 @@ process_win32_write(struct process_t *process, buf_t *buffer) process_win32_stdin_write_done); if (! ret) { - log_warn(LD_PROCESS, "WriteFileEx() failed: %s", - format_win32_error(GetLastError())); + error_code = GetLastError(); + + /* No need to log at warning level for these two. */ + if (error_code == ERROR_HANDLE_EOF || error_code == ERROR_BROKEN_PIPE) { + log_debug(LD_PROCESS, "WriteFileEx() returned EOF from pipe: %s", + format_win32_error(error_code)); + } else { + log_warn(LD_PROCESS, "WriteFileEx() failed: %s", + format_win32_error(error_code)); + } + win32_process->stdin_handle.reached_eof = true; return 0; } @@ -897,8 +906,17 @@ process_win32_read_from_handle(process_win32_handle_t *handle, callback); if (! ret) { - log_warn(LD_PROCESS, "ReadFileEx() failed: %s", - format_win32_error(GetLastError())); + error_code = GetLastError(); + + /* No need to log at warning level for these two. */ + if (error_code == ERROR_HANDLE_EOF || error_code == ERROR_BROKEN_PIPE) { + log_debug(LD_PROCESS, "ReadFileEx() returned EOF from pipe: %s", + format_win32_error(error_code)); + } else { + log_warn(LD_PROCESS, "ReadFileEx() failed: %s", + format_win32_error(error_code)); + } + handle->reached_eof = true; return bytes_available; }