From 24560ffe81e192ad39fc8c872bed22c6183f5fd9 Mon Sep 17 00:00:00 2001 From: Swung0x48 Date: Tue, 29 Sep 2026 02:26:38 -0400 Subject: [PATCH] [Fix] (MG_Remote): P9 W3 - a FATAL forward waits once per stall rather than once per line (MGLOG_F also marks survivable conditions), and F2 proves the flood got through on a live connection, inside TCP_USER_TIMEOUT --- MobileGL/MG_Remote/Transport/LogForward.cpp | 12 +++++++ MobileGL/MG_Remote/Transport/LogForward.h | 9 +++-- .../MG_Test/Wire/EventForfeitPeerTest.cpp | 34 ++++++++++++++---- MobileGL/MG_Test/Wire/LogForwardTest.cpp | 36 +++++++++++++++++++ 4 files changed, 82 insertions(+), 9 deletions(-) diff --git a/MobileGL/MG_Remote/Transport/LogForward.cpp b/MobileGL/MG_Remote/Transport/LogForward.cpp index 03a5a55d..305aebf1 100644 --- a/MobileGL/MG_Remote/Transport/LogForward.cpp +++ b/MobileGL/MG_Remote/Transport/LogForward.cpp @@ -189,10 +189,22 @@ namespace MobileGL::MG_Remote::Transport { return; } // FATAL: wait - bounded - until the sender has written this line and everything before it. + // + // ONCE PER STALL, NOT ONCE PER LINE. MGLOG_F is not only the last word before an abort: the + // tree also uses it for survivable conditions (the EGL loader's "Failed to load EGL function" + // lines, several in a row). If an earlier FATAL wait already ran out and the sender has not + // written a single item since, the peer is still not reading and a second wait would only + // spend another fatalFlushMs of this thread's time on the same answer - so it is counted as + // a timeout at once. The line itself is queued either way. + if (m_fatalGaveUpAtWritten == m_writtenSeq) { + ++m_counters.fatalFlushTimeouts; + return; + } const auto deadline = started + std::chrono::milliseconds(m_limits.fatalFlushMs); if (!m_cv.wait_until(lock, deadline, [this, seq] { return m_writtenSeq >= seq || m_counters.transportFailed; })) { ++m_counters.fatalFlushTimeouts; + m_fatalGaveUpAtWritten = m_writtenSeq; } } diff --git a/MobileGL/MG_Remote/Transport/LogForward.h b/MobileGL/MG_Remote/Transport/LogForward.h index 7c5c6066..958bbff1 100644 --- a/MobileGL/MG_Remote/Transport/LogForward.h +++ b/MobileGL/MG_Remote/Transport/LogForward.h @@ -43,8 +43,10 @@ // * FATAL is ERROR plus a wait: the logging thread is about to abort, and a line still in the // queue when it does is a line the client never gets - the one it most needs. So a FATAL // Offer waits until the sender has written everything up to and including it, for at most -// fatalFlushMs, and then returns whether or not the peer took it. (Log.cpp hands a FATAL line -// over outside the log mutex, so that wait holds nobody else's line.) +// fatalFlushMs, and then returns whether or not the peer took it - and once such a wait has run +// out, later FATAL lines do not wait again until the sender has written something (MGLOG_F also +// marks survivable conditions, several in a row). (Log.cpp hands a FATAL line over outside the +// log mutex, so that wait holds nobody else's line.) // * A LogFlush acknowledgement (OfferControlFrame) is queued BEHIND every line offered before // it, which is what makes MGPipeSyncPeerLog's promise ("every line before the flush is in the // file when the ack arrives") still true now that a line is not on the wire when MGLOG returns. @@ -176,6 +178,9 @@ namespace MobileGL::MG_Remote::Transport { std::uint64_t m_errorBytes = 0; std::uint64_t m_nextSeq = 1; std::uint64_t m_writtenSeq = 0; // the seq of the last item the sender finished with + // m_writtenSeq when a FATAL wait last ran out; while it has not moved since, the next FATAL + // does not wait again (Offer). ~0 = no wait has run out. + std::uint64_t m_fatalGaveUpAtWritten = ~0ull; std::uint64_t m_urgent = 0; // FATAL lines and control frames queued: do not pace // A gap not yet marked in the stream, per class. std::uint64_t m_gapLossyLines = 0; diff --git a/MobileGL/MG_Test/Wire/EventForfeitPeerTest.cpp b/MobileGL/MG_Test/Wire/EventForfeitPeerTest.cpp index 5b95fa7e..5d8e4697 100644 --- a/MobileGL/MG_Test/Wire/EventForfeitPeerTest.cpp +++ b/MobileGL/MG_Test/Wire/EventForfeitPeerTest.cpp @@ -148,8 +148,16 @@ namespace { // instead of the server: this host's tcp_rmem lets a receive buffer autotune to 32 MiB, and a // peer whose socket takes the whole flood is not a peer that stopped reading. constexpr int kStalledReceiveBufferBytes = 16 * 1024; - // How long the apply thread gets to log the whole flood with nobody reading it. It needs well - // under a second; the budget is for a loaded runner. + // How long the apply thread gets to log the whole flood with nobody reading it: it needs about + // half a second here. THE CEILING IS NOT SLACK, IT IS THE KERNEL'S. SocketTransport sets + // TCP_USER_TIMEOUT to 5000 ms on every TCP connection (SocketTransport.cpp), so a peer that keeps + // a zero window for 5 s has its control connection aborted (ETIMEDOUT) - which ends ANY stall, + // including a forward that held the apply thread in a socket write the whole time (the red-once + // run: the flood "completed" at 5.4 s, after the abort released it). So "the flood got through + // while nobody read" only means "the apply thread was not held" if it happened well inside those + // 5 s, on a live connection. + constexpr std::uint32_t kFloodWithinMs = 4000; + // The overall budget for the undrained arm's forfeit and reap, which do not race the kernel. constexpr std::uint32_t kFloodBudgetMs = 15000; // The longest one forward may take a logging thread (the summary's max-offer-us). The channel // spends a lock and a copy; a forward that waited on the peer would spend the whole stall. @@ -977,8 +985,15 @@ namespace { const int code = WaitChild(peer, std::chrono::milliseconds(5000)); releasePeer.pid = -1; ::close(synced[0]); - FAIL() << "the flood peer did not get its records out (child exit " << code << ")\n" - << ServerLog(logBase).substr(0, 20000); + // In the undrained arm the peer's ResourceCreate / Respecify / SubData WAIT behind the + // flood (exit 14..16): the apply thread has to get through 400 flooding records to answer + // them, so a forward that holds it shows up here first. + FAIL() << "the flood peer did not get its records out (child exit " << code + << (code >= kBufferCreate && code <= kBufferContent + ? ": its wait behind the flood was never answered - the apply thread was held" + : "") + << ")\n" + << LineWith(ServerLog(logBase), "log forwarding ended"); } const auto every = std::chrono::milliseconds(200); @@ -987,12 +1002,17 @@ namespace { // own log must reach the flood's last record: every one of the kFloodRecords records is // applied (and logs its ERROR line) while the control connection takes no byte. A forward // that waits on the socket stalls the apply thread a few MiB in, and this never arrives. - const long long reachedMs = - WaitForLog(logBase, kFloodErrorNeedle, kFloodRecords, std::chrono::milliseconds(kFloodBudgetMs), every); + const long long reachedMs = WaitForLog(logBase, kFloodErrorNeedle, kFloodRecords, + std::chrono::milliseconds(kFloodWithinMs), + std::chrono::milliseconds(50)); ASSERT_GE(reachedMs, 0) << "the apply thread did not get through the flood while its client was not " "reading control - it was held by logging (" << Count(ServerLog(logBase), kFloodErrorNeedle) << " of " << kFloodRecords - << " records' ERROR lines logged after " << kFloodBudgetMs << " ms)"; + << " records' ERROR lines logged after " << kFloodWithinMs << " ms)"; + // ...and on a LIVE connection: not released by the kernel aborting a zero-window socket. + ASSERT_EQ(ServerLog(logBase).find("recv failed"), std::string::npos) + << "the flood finished only after the control connection died - the stall was ended by " + "TCP_USER_TIMEOUT, not survived"; // (2) The peer reads again and synchronises its log. const char go = 1; ASSERT_EQ(::write(release[1], &go, 1), 1); diff --git a/MobileGL/MG_Test/Wire/LogForwardTest.cpp b/MobileGL/MG_Test/Wire/LogForwardTest.cpp index ac6af229..7977c5c3 100644 --- a/MobileGL/MG_Test/Wire/LogForwardTest.cpp +++ b/MobileGL/MG_Test/Wire/LogForwardTest.cpp @@ -315,6 +315,35 @@ namespace { EXPECT_EQ(CapturedLevelOf("w3-logger-marker client-side"), -1); } + // The other kind: the in-process display server's SESSION-scoped forwarder (SetSessionLogForwarder), + // which forwards only from the thread that installed it and threads that opted in, OUTSIDE the + // log mutex. Same levels, including FATAL. + TEST(LogForwardLogger, TheSessionScopedForwarderGetsEachLevelToo) { + (void)LogBase(); + std::thread session([] { + Debug::SetThreadLogRole(Debug::LogRole::Server); + Debug::SetSessionLogForwarder(&Capture, nullptr); + MGLOG_I("w3-session-marker info"); + MGLOG_W("w3-session-marker warn"); + MGLOG_E("w3-session-marker error"); + MGLOG_F("w3-session-marker fatal"); + // A server-role thread that did NOT opt in is not this session's: it forwards nothing. + std::thread other([] { + Debug::SetThreadLogRole(Debug::LogRole::Server); + MGLOG_E("w3-session-marker not-opted-in"); + }); + other.join(); + Debug::SetLogForwarder(nullptr, nullptr); + Debug::SetThreadForwardsLogToPeer(false); + }); + session.join(); + EXPECT_EQ(CapturedLevelOf("w3-session-marker info"), MOBILEGL_LOG_LEVEL_INFO); + EXPECT_EQ(CapturedLevelOf("w3-session-marker warn"), MOBILEGL_LOG_LEVEL_WARN); + EXPECT_EQ(CapturedLevelOf("w3-session-marker error"), MOBILEGL_LOG_LEVEL_ERROR); + EXPECT_EQ(CapturedLevelOf("w3-session-marker fatal"), MOBILEGL_LOG_LEVEL_FATAL); + EXPECT_EQ(CapturedLevelOf("w3-session-marker not-opted-in"), -1); + } + TEST(LogForwardLogger, APeerLineIsFiledUnderTheLevelTheWireCarried) { const std::string serverLog = Debug::RoleLogPath(LogBase().c_str(), Debug::LogRole::Server); // A line the server formatted is written as it came - its header already names its level. @@ -532,6 +561,13 @@ namespace { EXPECT_GE(waited, 250); EXPECT_LT(waited, 3000); EXPECT_EQ(channel.Counters().fatalFlushTimeouts, 1u); + // A second FATAL while nothing has been written since: the stall is known, the line is + // queued and the Offer does not spend another bound on the same answer (MGLOG_F also + // marks survivable conditions, and they come in runs). + const auto again = Clock::now(); + channel.Offer(MOBILEGL_LOG_LEVEL_FATAL, "fatal held again\n"); + EXPECT_LT(MillisecondsSince(again), 150) << "a second FATAL waited out the bound again on a known stall"; + EXPECT_EQ(channel.Counters().fatalFlushTimeouts, 2u); } }