Skip to content

Commit b119273

Browse files
authored
[fix](load) Keep graceful BE stop bounded when an audit stream load is in flight (#66797)
### What problem does this PR solve? Issue Number: close #66796 Problem Summary: A graceful BE shutdown could hang for up to 10 minutes and fail the pipeline's "stop grace" check. `doris_main()` stops the servers first (`Http service stopped` -> `Brpc service stopped` -> `Backend Service stopped`) and only then calls `ExecEnv::destroy()`, which reaches `SAFE_STOP(_stream_load_recorder_manager)` and joins the recorder's worker `std::thread`. If that worker is inside `_send_stream_load()` at the time, its request is a stream load against this BE's own http endpoint, which has already been torn down, so the load can never complete and the request only returns once the `DEFAULT_STREAM_LOAD_TIMEOUT_SEC = 600` curl timeout expires. The join blocks for that long. Deployment scripts give graceful stop a 10 minute budget, so whenever the race fires the stop check is guaranteed to lose it and the BE gets `kill -ABRT`ed. The window is narrow (an audit batch has to be in flight within about one worker iteration of the service teardown), which is why it fired only once in the last 30 NonConcurrentRegression runs, but any BE with a pending audit-log batch at stop time can hang this way. The PR applies three changes, each of which bounds the wait on its own: 1. **Ordering** — `doris_main()` stops the recorder manager *before* tearing down the http service, so on the normal path the last audit batch is flushed against a live server and the worker is already gone by the time `ExecEnv::destroy()` runs. `stop()` is idempotent, so the existing `SAFE_STOP()` in `destroy()` becomes a no-op. 2. **Interruptible send** — new `HttpClient::set_abort_callback()` registers a functor that libcurl polls through `CURLOPT_XFERINFOFUNCTION`, roughly once per second while the connection is idle. Returning true aborts the transfer with `CURLE_ABORTED_BY_CALLBACK` instead of running to `CURLOPT_TIMEOUT_MS`. `StreamLoadRecorderManager` hooks its `_stop` flag up to it, which covers both a request that is already in flight when `stop()` is called and one that races its way past the check in 3. 3. **No new work after stop** — the worker no longer starts an audit load once shutdown has begun, and waits on a condition variable instead of an unconditional 1s sleep, so `stop()` wakes it immediately rather than after up to a second. `stop()` now also logs on completion. The original hang was hard to locate in the log precisely because a raw `std::thread::join()` is silent, unlike doris `Thread::join`, which prints `Waited for ...ms trying to join`. The 600s curl timeout itself is left alone: it is a sane bound for a load that is not racing shutdown, and the abort hook makes it irrelevant for shutdown. ### Release note Fix a graceful BE shutdown that could hang for up to 10 minutes when an audit log stream load was in flight while the BE's http service was being stopped. ### Check List (For Author) - Test - [x] Unit Test `HttpClientTest.abort_in_flight_request` points an `HttpClient` at a listening socket that is never accepted from — the kernel completes the handshake and buffers the request, but no response ever comes, which is exactly what an audit stream load looks like once the http service serving it is gone. With `CURLOPT_TIMEOUT_MS` at 60s, the abort callback is raised 300ms in and the request has to end well before the timeout. Verified separately against the libcurl the BE links (8.2.1) that the progress callback is polled while idle-waiting: the request ends in ~1.2s with `CURLE_ABORTED_BY_CALLBACK` (callback invoked 13 times) rather than at 60s. The shutdown ordering itself is not unit-testable — it needs a full BE stop with an audit batch in flight, which is the race described in the issue.
1 parent b9ee837 commit b119273

7 files changed

Lines changed: 143 additions & 2 deletions

File tree

be/src/load/stream_load/stream_load_recorder_manager.cpp

Lines changed: 23 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -80,21 +80,38 @@ void StreamLoadRecorderManager::_load_last_fetch_key() {
8080
}
8181

8282
void StreamLoadRecorderManager::stop() {
83-
_stop = true;
83+
{
84+
std::lock_guard<std::mutex> lock(_stop_mutex);
85+
_stop = true;
86+
}
87+
// Wakes the worker from its idle wait, and aborts the audit stream load it may
88+
// currently be blocked on, see the abort callback in _send_stream_load().
89+
_stop_cv.notify_all();
8490
if (_worker_thread.joinable()) {
8591
_worker_thread.join();
92+
LOG(INFO) << "StreamLoadRecorderManager is stopped";
8693
}
8794
}
8895

8996
void StreamLoadRecorderManager::_worker_thread_func() {
9097
SCOPED_ATTACH_TASK(_mem_tracker);
9198
while (!_stop) {
9299
_fetch_and_buffer_records();
100+
// Do not start a new audit stream load once shutdown has begun. The load is served
101+
// by this BE's own http service, which is about to go away.
102+
if (_stop) {
103+
break;
104+
}
93105
_load_if_necessary();
94-
std::this_thread::sleep_for(std::chrono::seconds(1));
106+
_wait_for_stop(1000);
95107
}
96108
}
97109

110+
void StreamLoadRecorderManager::_wait_for_stop(int64_t wait_ms) {
111+
std::unique_lock<std::mutex> lock(_stop_mutex);
112+
_stop_cv.wait_for(lock, std::chrono::milliseconds(wait_ms), [this]() { return _stop.load(); });
113+
}
114+
98115
void StreamLoadRecorderManager::_fetch_and_buffer_records() {
99116
if (!_recorder) {
100117
LOG(WARNING) << "StreamLoadRecorder is not initialized";
@@ -262,6 +279,10 @@ Status StreamLoadRecorderManager::_send_stream_load(const std::string& data) {
262279
if (!st.ok()) {
263280
return Status::InternalError("Failed to init http client: {}", st.to_string());
264281
}
282+
// This load is served by this BE's own http service. Once shutdown starts that service
283+
// stops answering, and without an abort hook the request would sit here for the full
284+
// DEFAULT_STREAM_LOAD_TIMEOUT_SEC, blocking the join() in stop().
285+
client.set_abort_callback([this]() { return _stop.load(); });
265286
client.set_authorization("Basic YWRtaW46");
266287
client.set_header("Expect", "100-continue");
267288
client.set_content_type("text/plain; charset=UTF-8");

be/src/load/stream_load/stream_load_recorder_manager.h

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,8 +18,10 @@
1818
#pragma once
1919

2020
#include <atomic>
21+
#include <condition_variable>
2122
#include <cstdint>
2223
#include <memory>
24+
#include <mutex>
2325
#include <string>
2426
#include <thread>
2527

@@ -57,6 +59,13 @@ class StreamLoadRecorderManager {
5759

5860
void start();
5961

62+
// Stops the worker thread and waits for it to exit. Aborts the audit stream load that
63+
// the worker may currently be running, so that this returns within about a second even
64+
// if the request would never be answered.
65+
//
66+
// The manager sends its records to this BE's own http service, so it must be stopped
67+
// before that service is torn down. doris_main() does that explicitly; the SAFE_STOP()
68+
// in ExecEnv::destroy() is then a no-op. Calling this more than once is safe.
6069
void stop();
6170

6271
private:
@@ -80,12 +89,17 @@ class StreamLoadRecorderManager {
8089

8190
void _reset_batch(int64_t current_time);
8291

92+
// Waits at most `wait_ms` for stop() to be called. The caller re-checks _stop itself.
93+
void _wait_for_stop(int64_t wait_ms);
94+
8395
private:
8496
std::shared_ptr<StreamLoadRecorder> _recorder;
8597
std::shared_ptr<MemTrackerLimiter> _mem_tracker;
8698

8799
std::thread _worker_thread;
88100
std::atomic<bool> _stop;
101+
std::mutex _stop_mutex;
102+
std::condition_variable _stop_cv;
89103

90104
faststring _buffer;
91105

be/src/runtime/exec_env.h

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -301,6 +301,9 @@ class ExecEnv {
301301

302302
StreamLoadExecutor* stream_load_executor() { return _stream_load_executor.get(); }
303303
RoutineLoadTaskExecutor* routine_load_task_executor() { return _routine_load_task_executor; }
304+
StreamLoadRecorderManager* stream_load_recorder_manager() {
305+
return _stream_load_recorder_manager;
306+
}
304307
HeartbeatFlags* heartbeat_flags() { return _heartbeat_flags; }
305308
FileMetaCache* file_meta_cache() { return _file_meta_cache; }
306309
MemTableMemoryLimiter* memtable_memory_limiter() { return _memtable_memory_limiter.get(); }

be/src/service/doris_main.cpp

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,7 @@
7373
#include "common/signal_handler.h"
7474
#include "common/status.h"
7575
#include "io/cache/block_file_cache_factory.h"
76+
#include "load/stream_load/stream_load_recorder_manager.h"
7677
#include "runtime/exec_env.h"
7778
#include "runtime/user_function_cache.h"
7879
#include "service/arrow_flight/flight_sql_service.h"
@@ -731,6 +732,15 @@ int main(int argc, char** argv) {
731732
heartbeat_thrift_starter->stop();
732733
heartbeat_thrift_starter->join();
733734
LOG(INFO) << "Heartbeat server stopped";
735+
// The stream load recorder manager writes its audit records through this BE's own http
736+
// service, so it has to be stopped while that service is still up. Otherwise an audit
737+
// load that is in flight here can never be answered, and it blocks the join() done by
738+
// SAFE_STOP(_stream_load_recorder_manager) in ExecEnv::destroy() for up to the stream
739+
// load timeout, which is longer than the grace period of stop_be.sh --grace.
740+
if (auto* recorder_manager = exec_env->stream_load_recorder_manager();
741+
recorder_manager != nullptr) {
742+
recorder_manager->stop();
743+
}
734744
// TODO(zhiqiang): http_service
735745
http_starter->stop();
736746
http_starter->join();

be/src/service/http/http_client.cpp

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -295,6 +295,8 @@ Status HttpClient::init(const std::string& url, bool set_fail_on_error) {
295295
curl_slist_free_all(_header_list);
296296
_header_list = nullptr;
297297
}
298+
// curl_easy_reset() dropped the progress callback options, so drop the functor too.
299+
_abort_callback = nullptr;
298300
// set error_buf
299301
_error_buf[0] = 0;
300302
auto code = curl_easy_setopt(_curl, CURLOPT_ERRORBUFFER, _error_buf);
@@ -388,6 +390,26 @@ void HttpClient::set_method(HttpMethod method) {
388390
}
389391
}
390392

393+
void HttpClient::set_abort_callback(std::function<bool()> callback) {
394+
_abort_callback = std::move(callback);
395+
if (!_abort_callback) {
396+
curl_easy_setopt(_curl, CURLOPT_NOPROGRESS, 1L);
397+
return;
398+
}
399+
400+
curl_xferinfo_callback xferinfo = [](void* param, curl_off_t /*dltotal*/, curl_off_t /*dlnow*/,
401+
curl_off_t /*ultotal*/, curl_off_t /*ulnow*/) -> int {
402+
auto* client = (HttpClient*)param;
403+
// A non-zero return value makes libcurl abort the transfer with
404+
// CURLE_ABORTED_BY_CALLBACK.
405+
return client->_abort_callback() ? 1 : 0;
406+
};
407+
curl_easy_setopt(_curl, CURLOPT_XFERINFOFUNCTION, xferinfo);
408+
curl_easy_setopt(_curl, CURLOPT_XFERINFODATA, (void*)this);
409+
// libcurl only calls the progress callback when the progress meter is enabled.
410+
curl_easy_setopt(_curl, CURLOPT_NOPROGRESS, 0L);
411+
}
412+
391413
void HttpClient::set_speed_limit() {
392414
curl_easy_setopt(_curl, CURLOPT_LOW_SPEED_LIMIT, config::download_low_speed_limit_kbps * 1024);
393415
curl_easy_setopt(_curl, CURLOPT_LOW_SPEED_TIME, config::download_low_speed_time);

be/src/service/http/http_client.h

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -117,6 +117,17 @@ class HttpClient {
117117
curl_easy_setopt(_curl, CURLOPT_TIMEOUT_MS, timeout_ms);
118118
}
119119

120+
// Register a callback that libcurl polls while the request is in flight: often while
121+
// data is flowing, and about once per second when the connection is idle. Returning
122+
// true aborts the transfer right away, so `execute()` fails instead of blocking until
123+
// CURLOPT_TIMEOUT_MS expires.
124+
//
125+
// This is for callers that must be able to give up on a request which may never be
126+
// answered, e.g. a background worker that is being stopped while the http service
127+
// serving its request is going away. Must be called after init(), which resets all
128+
// curl options. Passing an empty callback clears a previously registered one.
129+
void set_abort_callback(std::function<bool()> callback);
130+
120131
// used to get content length
121132
// return -1 as error
122133
Status get_content_length(uint64_t* length) const {
@@ -198,6 +209,7 @@ class HttpClient {
198209
CURL* _curl = nullptr;
199210
using HttpCallback = std::function<bool(const void* data, size_t length)>;
200211
const HttpCallback* _callback = nullptr;
212+
std::function<bool()> _abort_callback;
201213
char _error_buf[CURL_ERROR_SIZE];
202214
curl_slist* _header_list = nullptr;
203215
HttpMethod _method = GET;

be/test/service/http/http_client_test.cpp

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,12 +21,18 @@
2121
#include <fcntl.h>
2222
#include <gtest/gtest-message.h>
2323
#include <gtest/gtest-test-part.h>
24+
#include <netinet/in.h>
2425
#include <sys/mman.h>
26+
#include <sys/socket.h>
2527
#include <sys/stat.h>
2628
#include <unistd.h>
2729

30+
#include <atomic>
2831
#include <boost/algorithm/string/predicate.hpp>
32+
#include <chrono>
33+
#include <cstring>
2934
#include <filesystem>
35+
#include <thread>
3036

3137
#include "gtest/gtest_pred_impl.h"
3238
#include "io/fs/local_file_system.h"
@@ -669,4 +675,57 @@ TEST_F(HttpClientTest, batch_download) {
669675
EXPECT_TRUE(st.ok());
670676
}
671677

678+
TEST_F(HttpClientTest, abort_in_flight_request) {
679+
// A listening socket that is never accepted from. The kernel completes the handshake
680+
// and buffers the request, so the client believes it is connected, but no response ever
681+
// comes back. This is what an audit stream load looks like when the http service that
682+
// was supposed to serve it has been torn down.
683+
int listen_fd = socket(AF_INET, SOCK_STREAM, 0);
684+
ASSERT_GE(listen_fd, 0);
685+
struct sockaddr_in addr;
686+
memset(&addr, 0, sizeof(addr));
687+
addr.sin_family = AF_INET;
688+
addr.sin_addr.s_addr = htonl(INADDR_LOOPBACK);
689+
addr.sin_port = 0; // let the kernel pick a free port
690+
ASSERT_EQ(0, bind(listen_fd, reinterpret_cast<struct sockaddr*>(&addr), sizeof(addr)));
691+
ASSERT_EQ(0, listen(listen_fd, 8));
692+
socklen_t addr_len = sizeof(addr);
693+
ASSERT_EQ(0, getsockname(listen_fd, reinterpret_cast<struct sockaddr*>(&addr), &addr_len));
694+
std::string url = "http://127.0.0.1:" + std::to_string(ntohs(addr.sin_port)) + "/no_answer";
695+
696+
HttpClient client;
697+
auto st = client.init(url);
698+
EXPECT_TRUE(st.ok()) << st;
699+
client.set_method(GET);
700+
// Much longer than the abort is expected to take, so that finishing early can only be
701+
// the abort callback and not the timeout.
702+
client.set_timeout_ms(60 * 1000);
703+
std::atomic<bool> should_abort {false};
704+
client.set_abort_callback([&should_abort]() { return should_abort.load(); });
705+
706+
// Ask for the abort only once the request is on the wire, like a shutdown starting
707+
// while a worker is already blocked inside execute().
708+
std::thread aborter([&should_abort]() {
709+
std::this_thread::sleep_for(std::chrono::milliseconds(300));
710+
should_abort = true;
711+
});
712+
713+
auto start = std::chrono::steady_clock::now();
714+
std::string response;
715+
st = client.execute(&response);
716+
auto elapsed_ms = std::chrono::duration_cast<std::chrono::milliseconds>(
717+
std::chrono::steady_clock::now() - start)
718+
.count();
719+
aborter.join();
720+
close(listen_fd);
721+
722+
EXPECT_FALSE(st.ok());
723+
// The request really was stuck waiting rather than failing outright, ...
724+
EXPECT_GE(elapsed_ms, 300) << "request did not reach the server, it took " << elapsed_ms
725+
<< "ms";
726+
// ... and the abort ended it instead of CURLOPT_TIMEOUT_MS. libcurl polls the callback
727+
// about once a second while the connection is idle.
728+
EXPECT_LT(elapsed_ms, 15000) << "request was not aborted, it took " << elapsed_ms << "ms";
729+
}
730+
672731
} // namespace doris

0 commit comments

Comments
 (0)