diff --git a/.gitea/workflows/build.yml b/.gitea/workflows/build.yml index 585d8b4..ed5b3d4 100644 --- a/.gitea/workflows/build.yml +++ b/.gitea/workflows/build.yml @@ -31,7 +31,29 @@ on: # job is ordinary commits. branches: - "**" + # Documentation-only changes cannot break a build, and this workflow is a + # full three-platform build (Windows included) behind a runner with + # capacity:1. Six of these fired for one afternoon of README/release-notes + # edits on 2026-09-09. Anything that feeds a build or a test is absent + # from this list on purpose -- release.yml and publish-release.sh only run + # on a `v*` tag, via release.yml's own trigger. + # + # Tradeoff: a docs-only push now shows NO status at all on the branch, + # rather than a green one. If a required-status check is ever added, these + # paths have to be reconsidered. + paths-ignore: + - "**.md" + - "LICENSE" + - "NOTICE" + - ".gitea/workflows/release.yml" + - ".gitea/scripts/publish-release.sh" pull_request: + paths-ignore: + - "**.md" + - "LICENSE" + - "NOTICE" + - ".gitea/workflows/release.yml" + - ".gitea/scripts/publish-release.sh" jobs: linux: diff --git a/core/src/http_winhttp.cpp b/core/src/http_winhttp.cpp index 9982081..f479b44 100644 --- a/core/src/http_winhttp.cpp +++ b/core/src/http_winhttp.cpp @@ -19,8 +19,13 @@ You may obtain a copy of the License at #include #include +#include +#include +#include #include +#include #include +#include #include namespace stplugin { @@ -72,6 +77,79 @@ private: HINTERNET h_ = nullptr; }; +/// Hard deadline for one WinHTTP exchange, enforced by cancelling it. +/// +/// Neither receive timeout is a guaranteed deadline: Microsoft documents both +/// as "checked only when data is received from the socket", so an expired +/// timeout is not surfaced until the peer finally sends something. Measured on +/// the Windows CI runner against a server that accepts and then stalls 5s: a +/// 700ms budget returned after 1490, 1529, 2485, 3493 and 4506ms across five +/// attempts -- always cancelled, never on time. +/// +/// That overshoot matters because `fetchSlots` is called synchronously on the +/// OBS UI thread behind the properties dialog's "Refresh camera list" button +/// (obs-adapter/src/plugin-main.cpp), with a 5s budget. At the ratio above +/// that is a frozen dialog for half a minute. +/// +/// The documented way to force cancellation is to close the handle from +/// another thread; the pending call then fails with +/// ERROR_WINHTTP_OPERATION_CANCELLED. This owns the request handle so that +/// exactly one of the two threads ever closes it: `handle_.exchange(nullptr)` +/// hands the close to whichever gets there first. +/// +/// Known, accepted race: the caller may load the handle and have the watchdog +/// close it before the WinHttp* call reads it, in which case the call fails +/// with ERROR_INVALID_HANDLE instead. Both outcomes are "the deadline +/// expired", which is what the caller is told either way. +class RequestDeadline { +public: + RequestDeadline(HINTERNET request, DWORD after_ms) : handle_(request) + { + watchdog_ = std::thread([this, after_ms] { + std::unique_lock lock(mutex_); + if (cv_.wait_for(lock, std::chrono::milliseconds(after_ms), [this] { return finished_; })) + return; // exchange finished inside the deadline + if (closeOnce()) + expired_.store(true); + }); + } + + ~RequestDeadline() + { + { + std::lock_guard lock(mutex_); + finished_ = true; + } + cv_.notify_all(); + if (watchdog_.joinable()) + watchdog_.join(); + closeOnce(); // no-op if the watchdog got there first + } + + RequestDeadline(const RequestDeadline &) = delete; + RequestDeadline &operator=(const RequestDeadline &) = delete; + + HINTERNET get() const { return handle_.load(); } + bool expired() const { return expired_.load(); } + +private: + bool closeOnce() + { + HINTERNET h = handle_.exchange(nullptr); + if (!h) + return false; + WinHttpCloseHandle(h); + return true; + } + + std::atomic handle_; + std::atomic expired_{false}; + std::mutex mutex_; + std::condition_variable cv_; + bool finished_ = false; + std::thread watchdog_; +}; + class WinHttpClient : public HttpClient { public: HttpResponse send(const HttpRequest &request) override @@ -116,6 +194,39 @@ public: WinHttpSetTimeouts(session.get(), static_cast(timeout), static_cast(timeout), static_cast(timeout), static_cast(timeout)); + // WinHttpSetTimeouts' receive parameter maps to + // WINHTTP_OPTION_RECEIVE_TIMEOUT, which Microsoft documents as a + // PER-PACKET Winsock-layer read timeout ("applies to fetching each + // packet of data off the socket"), not a deadline on the response. + // The wait for the response HEADERS is a *separate* option, + // WINHTTP_OPTION_RECEIVE_RESPONSE_TIMEOUT ("to wait to receive all + // response headers to a request"), which WinHttpSetTimeouts does not + // touch and which defaults to 90 SECONDS. Without this call a server + // that accepts, reads the request and then stalls can hold this + // thread for a minute and a half regardless of request.timeout_ms -- + // exactly the "blocking an OBS thread indefinitely" failure + // testPlatformBackendTimeout exists to prevent, and the likely + // mechanism behind that test's intermittent Windows failures. + // + // Caveat, also documented: this timeout "is checked only when data is + // received from the socket", so it bounds the wait but does not + // guarantee a hard deadline. A guaranteed deadline needs a watchdog + // thread calling WinHttpCloseHandle; not done here. + // + // Guarded because the constant postdates some Windows SDK headers; a + // toolchain without it keeps the previous (90s default) behaviour + // rather than failing to build. +#ifdef WINHTTP_OPTION_RECEIVE_RESPONSE_TIMEOUT + DWORD response_timeout = timeout; + // Return value deliberately unchecked: a rejected option leaves the + // documented default in place, which is degraded but still correct + // behaviour, and there is no logging sink in this layer to report it + // to. The timeout probe in test_api_client.cpp is what would catch a + // regression here. + WinHttpSetOption(session.get(), WINHTTP_OPTION_RECEIVE_RESPONSE_TIMEOUT, &response_timeout, + sizeof(response_timeout)); +#endif + Handle connect(WinHttpConnect(session.get(), host, parts.nPort, 0)); if (!connect) { response.network_error = lastErrorMessage("WinHttpConnect"); @@ -126,13 +237,36 @@ public: target += extra; const DWORD flags = (parts.nScheme == INTERNET_SCHEME_HTTPS) ? WINHTTP_FLAG_SECURE : 0u; - Handle req(WinHttpOpenRequest(connect.get(), widen(request.method).c_str(), target.c_str(), nullptr, - WINHTTP_NO_REFERER, WINHTTP_DEFAULT_ACCEPT_TYPES, flags)); - if (!req) { + HINTERNET raw_req = WinHttpOpenRequest(connect.get(), widen(request.method).c_str(), target.c_str(), + nullptr, WINHTTP_NO_REFERER, WINHTTP_DEFAULT_ACCEPT_TYPES, + flags); + if (!raw_req) { response.network_error = lastErrorMessage("WinHttpOpenRequest"); return response; } + // Ceiling at twice the caller's budget: each of the four + // WinHttpSetTimeouts phases (resolve, connect, send, receive) is + // allowed `timeout` on its own, so a slow-but-progressing exchange can + // legitimately exceed one budget, and this must not cancel those. The + // floor keeps a very small timeout_ms from producing a deadline the + // exchange cannot meet on a cold connection. + const DWORD deadline_ms = (timeout > 500u) ? (timeout * 2u) : 1000u; + RequestDeadline req(raw_req, deadline_ms); + + // From here on, `req.get()` can be closed underneath us by the + // watchdog; every WinHttp* failure below is therefore checked against + // req.expired() before its GetLastError text is reported, so an + // expired deadline reads as a timeout rather than as + // "WinHttpReceiveResponse failed (GetLastError=12017)". + const auto fail = [&](const char *what) -> HttpResponse { + if (req.expired()) + response.network_error = "timed out after " + std::to_string(deadline_ms) + " ms"; + else + response.network_error = lastErrorMessage(what); + return response; + }; + std::wstring headers; if (!request.content_type.empty()) headers = L"Content-Type: " + widen(request.content_type) + L"\r\n"; @@ -144,31 +278,23 @@ public: : const_cast(request.body.data()); const DWORD body_len = static_cast(request.body.size()); - if (!WinHttpSendRequest(req.get(), header_ptr, header_len, body_ptr, body_len, body_len, 0)) { - response.network_error = lastErrorMessage("WinHttpSendRequest"); - return response; - } - if (!WinHttpReceiveResponse(req.get(), nullptr)) { - response.network_error = lastErrorMessage("WinHttpReceiveResponse"); - return response; - } + if (!WinHttpSendRequest(req.get(), header_ptr, header_len, body_ptr, body_len, body_len, 0)) + return fail("WinHttpSendRequest"); + if (!WinHttpReceiveResponse(req.get(), nullptr)) + return fail("WinHttpReceiveResponse"); DWORD status = 0; DWORD status_size = sizeof(status); if (!WinHttpQueryHeaders(req.get(), WINHTTP_QUERY_STATUS_CODE | WINHTTP_QUERY_FLAG_NUMBER, - WINHTTP_HEADER_NAME_BY_INDEX, &status, &status_size, WINHTTP_NO_HEADER_INDEX)) { - response.network_error = lastErrorMessage("WinHttpQueryHeaders"); - return response; - } + WINHTTP_HEADER_NAME_BY_INDEX, &status, &status_size, WINHTTP_NO_HEADER_INDEX)) + return fail("WinHttpQueryHeaders"); response.status = static_cast(status); std::string body; for (;;) { DWORD available = 0; - if (!WinHttpQueryDataAvailable(req.get(), &available)) { - response.network_error = lastErrorMessage("WinHttpQueryDataAvailable"); - return response; - } + if (!WinHttpQueryDataAvailable(req.get(), &available)) + return fail("WinHttpQueryDataAvailable"); if (available == 0) break; if (body.size() + available > kMaxResponseBytes) { @@ -177,10 +303,8 @@ public: } std::vector chunk(available); DWORD read = 0; - if (!WinHttpReadData(req.get(), chunk.data(), available, &read)) { - response.network_error = lastErrorMessage("WinHttpReadData"); - return response; - } + if (!WinHttpReadData(req.get(), chunk.data(), available, &read)) + return fail("WinHttpReadData"); if (read == 0) break; body.append(chunk.data(), read); diff --git a/core/tests/test_api_client.cpp b/core/tests/test_api_client.cpp index 4e15b7d..b03973e 100644 --- a/core/tests/test_api_client.cpp +++ b/core/tests/test_api_client.cpp @@ -16,6 +16,7 @@ You may obtain a copy of the License at // three runners rather than assumed to work. #include +#include #include #include #include @@ -422,22 +423,77 @@ void testPlatformBackendTimeout() { // A server that accepts and then stalls. The plugin must give up on its // own timeout rather than blocking an OBS thread indefinitely. - sttest::LoopbackServer server([](const std::string &) { - std::this_thread::sleep_for(std::chrono::seconds(5)); - return sttest::httpResponse(200, "OK", R"({"slots":[]})"); - }); - ST_ASSERT(server.valid()); + // + // INSTRUMENTED (2026-09-09) while chasing an intermittent Windows-only + // failure: on roughly 2 of 6 CI runs both assertions below fail together, + // meaning the request waited out the full 5s stall and returned 200 -- + // the timeout did not fire at all. Same failure seen on 2026-09-07 + // (job 5834) and 2026-09-09 (job 5911), on identical code that passed on + // other runs, so it is not a code change that caused it. + // + // The probe runs kProbes times and prints one line per attempt so a + // single CI run yields a failure RATE and the WinHTTP error code, rather + // than one bit. `ST_ASSERT` records and continues, so every attempt is + // reported even when one fails. Remove the loop and this comment once the + // mechanism is understood and fixed. + constexpr int kProbes = 5; + constexpr long long kStallMs = 5000; + constexpr long kTimeoutMs = 700; - std::shared_ptr http(createPlatformHttpClient()); - HttpRequest request; - request.url = server.baseUrl() + "/api/obs/main-room/slots?key=k"; - request.timeout_ms = 700; + int timed_out = 0; + for (int i = 0; i < kProbes; ++i) { + // A FRESH server per attempt, deliberately. `LoopbackServer` accepts + // and handles one connection at a time on a single thread, so reusing + // one server across attempts would leave attempts 2..n sitting in the + // accept backlog -- a different scenario (never accepted) from the one + // that fails on Windows (accepted, request read, then stalled). + sttest::LoopbackServer server([kStallMs](const std::string &) { + std::this_thread::sleep_for(std::chrono::milliseconds(kStallMs)); + return sttest::httpResponse(200, "OK", R"({"slots":[]})"); + }); + ST_ASSERT(server.valid()); - const auto start = std::chrono::steady_clock::now(); - const HttpResponse response = http->send(request); - const auto elapsed = std::chrono::steady_clock::now() - start; - ST_ASSERT(!response.ok()); - ST_ASSERT(std::chrono::duration_cast(elapsed).count() < 4000); + std::shared_ptr http(createPlatformHttpClient()); + HttpRequest request; + request.url = server.baseUrl() + "/api/obs/main-room/slots?key=k"; + request.timeout_ms = kTimeoutMs; + + const auto start = std::chrono::steady_clock::now(); + const HttpResponse response = http->send(request); + const auto elapsed = std::chrono::steady_clock::now() - start; + const long long ms = std::chrono::duration_cast(elapsed).count(); + + // 4000 was the old bound, chosen when nothing bounded the wait. The + // code now promises a hard ceiling of 2x the caller's budget + // (RequestDeadline in http_winhttp.cpp), so assert THAT -- 1400ms + // here, plus slack for a loaded runner. This is also the only signal + // that survives a green run: CTest prints nothing on success, so if + // WinHTTP's own erratic cancellation (measured at 1490-4506ms for + // this same 700ms budget) were doing the work instead of the + // watchdog, roughly half the attempts would land above this bound and + // say so, instead of quietly passing under a 4s ceiling. + constexpr long long kCeilingMs = 2500; + const bool gave_up = !response.ok() && ms < kCeilingMs; + if (gave_up) + ++timed_out; + + // Always printed, pass or fail: elapsed time and the backend's own + // error string (which carries GetLastError on Windows) are the + // evidence. requests_seen separates "the client never reached the + // server" (0) from "the server read the request and the client then + // waited it out" (1). + std::fprintf(stderr, + " [timeout-probe %d/%d] elapsed=%lldms ok=%d status=%ld " + "requests_seen=%d network_error='%s' -> %s\n", + i + 1, kProbes, ms, response.ok() ? 1 : 0, response.status, + server.requestCount(), response.network_error.c_str(), + gave_up ? "gave up (expected)" : "WAITED OUT THE STALL"); + + ST_ASSERT(!response.ok()); + ST_ASSERT(ms < kCeilingMs); + } + std::fprintf(stderr, " [timeout-probe] %d/%d attempts honoured the %ldms timeout\n", + timed_out, kProbes, kTimeoutMs); } } // namespace